p2000 failure due to empty reflog

p2000 failure due to empty reflog

[René Scharfe]

p2000 fails for me and reports:

   perf 18 - git checkout -f - (full-v3):
   running:
   			(
   				cd full-v3 &&
   				echo >>f2/f4/a &&
   				git checkout -f -
   			)

   error: pathspec '-' did not match any file(s) known to git

checkout fails because the reflog is empty, so the "-" can't be
resolved.  The pathspec error message is confusing, though.

The patch below adds a reflog entry and allows the script to
succeed.

Before the "test_perf_on_all git commit -a -m A", there are two
reflog entries in each of the five clones, after it there are
none.  How is that even possible?


---
 t/perf/p2000-sparse-operations.sh | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/t/perf/p2000-sparse-operations.sh b/t/perf/p2000-sparse-operations.sh
index 597626276f..8529e3d295 100755
--- a/t/perf/p2000-sparse-operations.sh
+++ b/t/perf/p2000-sparse-operations.sh
@@ -25,6 +25,7 @@ test_expect_success 'setup repo and indexes' '
 	git commit -m "level 0" &&
 	BLOB=$(git rev-parse HEAD:a) &&
 	OLD_COMMIT=$(git rev-parse HEAD) &&
+	test_export OLD_COMMIT &&
 	OLD_TREE=$(git rev-parse HEAD^{tree}) &&

 	for i in $(test_seq 1 3)
@@ -109,6 +110,14 @@ test_perf_on_all git status
 test_perf_on_all git add -A
 test_perf_on_all git add .
 test_perf_on_all git commit -a -m A
+
+test_expect_success 'add reflog entry' '
+	for repo in full-v3 full-v4 sparse-v3 sparse-v4
+	do
+		git -C $repo checkout $OLD_COMMIT
+	done
+'
+
 test_perf_on_all git checkout -f -

 test_done
--
2.33.0

Re: p2000 failure due to empty reflog

[Derrick Stolee]

On 10/2/2021 1:37 PM, René Scharfe wrote:
> p2000 fails for me and reports:
> 
>    perf 18 - git checkout -f - (full-v3):
>    running:
>    			(
>    				cd full-v3 &&
>    				echo >>f2/f4/a &&
>    				git checkout -f -
>    			)
> 
>    error: pathspec '-' did not match any file(s) known to git
> 
> checkout fails because the reflog is empty, so the "-" can't be
> resolved.  The pathspec error message is confusing, though.
> 
> The patch below adds a reflog entry and allows the script to
> succeed.
> 
> Before the "test_perf_on_all git commit -a -m A", there are two
> reflog entries in each of the five clones, after it there are
> none.  How is that even possible?

That is certainly confusing. Is there something about your global
(or local to your test repo) GC settings that cause an auto-GC to
prune the reflog aggressively?

> @@ -109,6 +110,14 @@ test_perf_on_all git status
>  test_perf_on_all git add -A
>  test_perf_on_all git add .
>  test_perf_on_all git commit -a -m A
> +
> +test_expect_success 'add reflog entry' '
> +	for repo in full-v3 full-v4 sparse-v3 sparse-v4
> +	do
> +		git -C $repo checkout $OLD_COMMIT
> +	done
> +'
> +
>  test_perf_on_all git checkout -f -

While I believe this will fix the situation, it might only be
a band-aid on the real problem of losing the reflog during the
test.

Thanks,
-Stolee

Re: p2000 failure due to empty reflog

[René Scharfe]

Am 04.10.21 um 21:55 schrieb Derrick Stolee:
> On 10/2/2021 1:37 PM, René Scharfe wrote:
>> p2000 fails for me and reports:
>>
>>    perf 18 - git checkout -f - (full-v3):
>>    running:
>>    			(
>>    				cd full-v3 &&
>>    				echo >>f2/f4/a &&
>>    				git checkout -f -
>>    			)
>>
>>    error: pathspec '-' did not match any file(s) known to git
>>
>> checkout fails because the reflog is empty, so the "-" can't be
>> resolved.  The pathspec error message is confusing, though.
>>
>> The patch below adds a reflog entry and allows the script to
>> succeed.
>>
>> Before the "test_perf_on_all git commit -a -m A", there are two
>> reflog entries in each of the five clones, after it there are
>> none.  How is that even possible?
>
> That is certainly confusing. Is there something about your global
> (or local to your test repo) GC settings that cause an auto-GC to
> prune the reflog aggressively?

Good point.  I have gc.auto=0 in my config, but the tests use their own,
empty config.  A trace shows that "git gc --auto --no-quiet" is started.
The following patch turns that off and allows the tests to succeed.

Not doing maintenance in parallel to a performance test is a good idea
anyway, but I still don't understand why it would empty the reflog --
that seems excessive, dangerous even.

One of the maintenance commands from the trace is "git reflog expire
--all".  If I put that in before the "checkout -" test (on top of the
patch below) then the reflog is emptied again and the test fails.

René

---
 t/perf/p2000-sparse-operations.sh | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/t/perf/p2000-sparse-operations.sh b/t/perf/p2000-sparse-operations.sh
index 597626276f..9a06904247 100755
--- a/t/perf/p2000-sparse-operations.sh
+++ b/t/perf/p2000-sparse-operations.sh
@@ -105,6 +105,13 @@ test_perf_on_all () {
 	done
 }

+test_expect_success 'disable housekeeping' '
+	for repo in full-v3 full-v4 sparse-v3 sparse-v4
+	do
+		git -C $repo config gc.auto 0
+	done
+'
+
 test_perf_on_all git status
 test_perf_on_all git add -A
 test_perf_on_all git add .
--
2.33.0

Re: p2000 failure due to empty reflog

[Junio C Hamano]

René Scharfe <l.s.r@web.de> writes:

> Good point.  I have gc.auto=0 in my config, but the tests use their own,
> empty config.  A trace shows that "git gc --auto --no-quiet" is started.
> The following patch turns that off and allows the tests to succeed.
>
> Not doing maintenance in parallel to a performance test is a good idea
> anyway,

Sounds like a sensible analysis, and I agree that it is a good idea
to by default disable the maintenance tasks in t/perf (possibly at a
more centralized place).

> but I still don't understand why it would empty the reflog --
> that seems excessive, dangerous even.
>
> One of the maintenance commands from the trace is "git reflog expire
> --all".  If I put that in before the "checkout -" test (on top of the
> patch below) then the reflog is emptied again and the test fails.
>
> René
>
> ---
>  t/perf/p2000-sparse-operations.sh | 7 +++++++
>  1 file changed, 7 insertions(+)
>
> diff --git a/t/perf/p2000-sparse-operations.sh b/t/perf/p2000-sparse-operations.sh
> index 597626276f..9a06904247 100755
> --- a/t/perf/p2000-sparse-operations.sh
> +++ b/t/perf/p2000-sparse-operations.sh
> @@ -105,6 +105,13 @@ test_perf_on_all () {
>  	done
>  }
>
> +test_expect_success 'disable housekeeping' '
> +	for repo in full-v3 full-v4 sparse-v3 sparse-v4
> +	do
> +		git -C $repo config gc.auto 0
> +	done
> +'
> +
>  test_perf_on_all git status
>  test_perf_on_all git add -A
>  test_perf_on_all git add .
> --
> 2.33.0

[PATCH] perf: disable automatic housekeeping

[René Scharfe]

Turn off automatic background maintenance for perf tests by default to
avoid interference with performance measurements.  Do that by using the
new file t/perf/config and using it as the system config file for perf
tests.  Future tests intended to measure gc performance can override
the setting locally or call "git gc" explicitly.

This fixes a breakage in p2000 caused by gc automatically emptying the
reflog due its fake dates from 2005 being older than 90 days.

Helped-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
Signed-off-by: René Scharfe <l.s.r@web.de>
---
 t/perf/config      | 2 ++
 t/perf/perf-lib.sh | 4 ++++
 2 files changed, 6 insertions(+)
 create mode 100644 t/perf/config

diff --git a/t/perf/config b/t/perf/config
new file mode 100644
index 0000000000..b92768b039
--- /dev/null
+++ b/t/perf/config
@@ -0,0 +1,2 @@
+[gc]
+	auto = 0
diff --git a/t/perf/perf-lib.sh b/t/perf/perf-lib.sh
index f74cfd35d6..4c4c568a37 100644
--- a/t/perf/perf-lib.sh
+++ b/t/perf/perf-lib.sh
@@ -27,6 +27,10 @@ TEST_NO_MALLOC_CHECK=t

 . ../test-lib.sh

+unset GIT_CONFIG_NOSYSTEM
+GIT_CONFIG_SYSTEM="$TEST_DIRECTORY/perf/config"
+export GIT_CONFIG_SYSTEM
+
 if test -n "$GIT_TEST_INSTALLED" -a -z "$PERF_SET_GIT_TEST_INSTALLED"
 then
 	error "Do not use GIT_TEST_INSTALLED with the perf tests.
--
2.33.0

"git reflog expire" blindly trusting timestamps in reflogs

[Ævar Arnfjörð Bjarmason]

[Changed subject]

On Sat, Oct 09 2021, René Scharfe wrote:

> Turn off automatic background maintenance for perf tests by default to
> avoid interference with performance measurements.

Turning off background GC during the perf tests seems like a good idea
in general, so I think this patch should go in. Even with the WIP
(haven't picked it up again in a while) test mode I menitoned in[1] it
still wouldn't make any sense to run detached background GC in t/perf.

Because first of all we take the repo as-is (hardlinks and all), so
changing it is a bug in itself.

But...

> Do that by using the
> new file t/perf/config and using it as the system config file for perf
> tests.  Future tests intended to measure gc performance can override
> the setting locally or call "git gc" explicitly.
>
> This fixes a breakage in p2000 caused by gc automatically emptying the
> reflog due its fake dates from 2005 being older than 90 days.

I think the behavior of git-reflog is probably just broken here and
needs fixing in general.

I.e. we don't actually change the ctime the relevant reflog files, so
surely this is pointing to deeper edge cases where e.g. someone might
import old history, only to see it wiped away due to the commits being
"old", but the mtime is just seconds/minutes old...

But I never had the time/chance to dig into that, maybe there's a good
reason for it.

Of course we can't rely on *just* the mtime since the whole point is to
expire older entries, we need to walk the file and trust the timestamps
therein. See the show_one_reflog_ent().

But my recollection & reading of [2] is that we nuke the whole
file. Surely we should have a "uh oh?" safeguard when we encounter a
file whose tip timestamp_t is from 2005, it's 2021, and our lstat()
mtime says it was changed seconds ago.

I.e. shouldn't reflog expiry at least have the invariant that nothing
should expire in a given file if the tip commit is old enough to be
expired, *AND* the mtime of the file is more recent than the expiry
epoch, because such a scenario points to either git's own test suite
(and we should just fake up the time there), or that we're about to
corrupt some user's repository because they're either doing similar
import work, or their clock was screwy?

> Helped-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
> Signed-off-by: René Scharfe <l.s.r@web.de>
> ---
>  t/perf/config      | 2 ++
>  t/perf/perf-lib.sh | 4 ++++
>  2 files changed, 6 insertions(+)
>  create mode 100644 t/perf/config
>
> diff --git a/t/perf/config b/t/perf/config
> new file mode 100644
> index 0000000000..b92768b039
> --- /dev/null
> +++ b/t/perf/config
> @@ -0,0 +1,2 @@
> +[gc]
> +	auto = 0
> diff --git a/t/perf/perf-lib.sh b/t/perf/perf-lib.sh
> index f74cfd35d6..4c4c568a37 100644
> --- a/t/perf/perf-lib.sh
> +++ b/t/perf/perf-lib.sh
> @@ -27,6 +27,10 @@ TEST_NO_MALLOC_CHECK=t
>
>  . ../test-lib.sh
>
> +unset GIT_CONFIG_NOSYSTEM
> +GIT_CONFIG_SYSTEM="$TEST_DIRECTORY/perf/config"
> +export GIT_CONFIG_SYSTEM
> +
>  if test -n "$GIT_TEST_INSTALLED" -a -z "$PERF_SET_GIT_TEST_INSTALLED"
>  then
>  	error "Do not use GIT_TEST_INSTALLED with the perf tests.

1. https://lore.kernel.org/git/8735pfjg47.fsf@evledraar.gmail.com/
2. https://lore.kernel.org/git/b25ac1cc-8e77-17e6-602a-b289c1e1cfeb@web.de/

Re: "git reflog expire" blindly trusting timestamps in reflogs

[Junio C Hamano]

Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:

> I.e. shouldn't reflog expiry at least have the invariant that nothing
> should expire in a given file if the tip commit is old enough to be
> expired, *AND* the mtime of the file is more recent than the expiry
> epoch, because such a scenario points to either git's own test suite
> (and we should just fake up the time there), or that we're about to
> corrupt some user's repository because they're either doing similar
> import work, or their clock was screwy?

A reflog whose entries (and possibly the containing file) have
inconsistent timestamps might need some care when pruning.  If the
time @{1} has is older than @{2}, there may be something fishy going
on.  Expiring @{1}, keep @{2}, and expire @{3} in such a case where
@{2} is exceptionally new but all others are older than expiry limit
is one possibility, but "entries out of order detected---do you want
to keep the one that is sandwiched between much older ones [y/N]?"
might be worth asking.  In any case, a reflog with such unordered
entries may not answer time-based @{1.week.ago} question correctly.

I do not think, at least by default, we should care about file's
mtime to the same degree, because it can easily be modified by
accident and because the timestamps on entries and mtime can come
from different time sources, and the local clock may be faster than
the fileserver's clock, resulting in the tip entry having a more
recent timestamp than the file's mtime.

Re: "git reflog expire" blindly trusting timestamps in reflogs

[Jeff King]

On Sat, Oct 09, 2021 at 04:57:20PM +0200, Ævar Arnfjörð Bjarmason wrote:

> On Sat, Oct 09 2021, René Scharfe wrote:
> 
> > Turn off automatic background maintenance for perf tests by default to
> > avoid interference with performance measurements.
> 
> Turning off background GC during the perf tests seems like a good idea
> in general, so I think this patch should go in. Even with the WIP
> (haven't picked it up again in a while) test mode I menitoned in[1] it
> still wouldn't make any sense to run detached background GC in t/perf.
> 
> Because first of all we take the repo as-is (hardlinks and all), so
> changing it is a bug in itself.

Lots of perf tests modify the repository. This is generally OK as Git
tends to write and rename tempfiles (breaking the hardlink) rather than
modifying anything in place. We also only do the hardlink thing for the
objects/ directory, so the scope is limited.

It does make me a little nervous, but to my knowledge we've never had a
perf test which hurt the original donor repo in this way. And there are
more subtle ways to screw things up with various filesystem references;
see 36e834abc1 (t/perf: avoid copying worktree files from test repo,
2021-02-26).

That's all just an aside; I agree that we should avoid background gc
just because it confuses performance tests.

-Peff

Re: p2000 failure due to empty reflog

[Ævar Arnfjörð Bjarmason]

On Mon, Oct 04 2021, Derrick Stolee wrote:

> On 10/2/2021 1:37 PM, René Scharfe wrote:
>> p2000 fails for me and reports:
>> 
>>    perf 18 - git checkout -f - (full-v3):
>>    running:
>>    			(
>>    				cd full-v3 &&
>>    				echo >>f2/f4/a &&
>>    				git checkout -f -
>>    			)
>> 
>>    error: pathspec '-' did not match any file(s) known to git
>> 
>> checkout fails because the reflog is empty, so the "-" can't be
>> resolved.  The pathspec error message is confusing, though.
>> 
>> The patch below adds a reflog entry and allows the script to
>> succeed.
>> 
>> Before the "test_perf_on_all git commit -a -m A", there are two
>> reflog entries in each of the five clones, after it there are
>> none.  How is that even possible?
>
> That is certainly confusing. Is there something about your global
> (or local to your test repo) GC settings that cause an auto-GC to
> prune the reflog aggressively?

Perhaps something to do with certain parts of the code doing a
time(NULL), and other parts faking up times to be 2005-something?

I have some WIP patches that run concurrent "git gc --auto" with a
detach across the whole test suite, and IIRC I had to search/replace all
time(NULL) with my own time() that faked up (looks it up) an epoch of
1113465166 to avoid this exact issue.

If you try doing that across our tests I think you'll find that the
@{-1} syntax (reflog-powered) will start failing.

But that's from vague memory, but perhaps it'll point you in the right
direction...

Re: p2000 failure due to empty reflog

[René Scharfe]

Am 05.10.21 um 23:38 schrieb Ævar Arnfjörð Bjarmason:
>
> On Mon, Oct 04 2021, Derrick Stolee wrote:
>
>> On 10/2/2021 1:37 PM, René Scharfe wrote:
>>> p2000 fails for me and reports:
>>>
>>>    perf 18 - git checkout -f - (full-v3):
>>>    running:
>>>    			(
>>>    				cd full-v3 &&
>>>    				echo >>f2/f4/a &&
>>>    				git checkout -f -
>>>    			)
>>>
>>>    error: pathspec '-' did not match any file(s) known to git
>>>
>>> checkout fails because the reflog is empty, so the "-" can't be
>>> resolved.  The pathspec error message is confusing, though.
>>>
>>> The patch below adds a reflog entry and allows the script to
>>> succeed.
>>>
>>> Before the "test_perf_on_all git commit -a -m A", there are two
>>> reflog entries in each of the five clones, after it there are
>>> none.  How is that even possible?
>>
>> That is certainly confusing. Is there something about your global
>> (or local to your test repo) GC settings that cause an auto-GC to
>> prune the reflog aggressively?
>
> Perhaps something to do with certain parts of the code doing a
> time(NULL), and other parts faking up times to be 2005-something?
>
> I have some WIP patches that run concurrent "git gc --auto" with a
> detach across the whole test suite, and IIRC I had to search/replace all
> time(NULL) with my own time() that faked up (looks it up) an epoch of
> 1113465166 to avoid this exact issue.
>
> If you try doing that across our tests I think you'll find that the
> @{-1} syntax (reflog-powered) will start failing.
>
> But that's from vague memory, but perhaps it'll point you in the right
> direction...
Yes, that helped.  The reflog entries have fake dates in 2005, and "git
reflog expire --all" called by "git gc --auto" deletes entries older
than 90 days based on the actual current time.

René