threads / discuss / 56629

p2000 failure due to empty reflog

Subject: p2000 failure due to empty reflog

## tl;dr

10 messages between Oct 2, 2021 and Oct 11, 2021.

replies: 9people: 5as markdown or json

René Scharfe· Oct 2, 2021, 17:37 UTC · lore
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
Derrick Stolee· Oct 4, 2021, 19:55 UTC · re: René Scharfe · lore

Re: p2000 failure due to empty reflog

On 10/2/2021 1:37 PM, René Scharfe wrote:
Show 21 quoted lines
> 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?

Show 13 quoted lines
> @@ -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

René Scharfe· Oct 5, 2021, 20:28 UTC · re: Derrick Stolee · lore

Re: p2000 failure due to empty reflog

Am 04.10.21 um 21:55 schrieb Derrick Stolee:
Show 26 quoted lines
> 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
Junio C Hamano· Oct 6, 2021, 16:59 UTC · re: René Scharfe · lore

Re: p2000 failure due to empty reflog

René Scharfe <l.s.r@web.de> writes:
Show 6 quoted lines
> 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).

Show 33 quoted lines
> 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
René Scharfe· Oct 9, 2021, 14:39 UTC · re: Junio C Hamano · lore

[PATCH] perf: disable automatic housekeeping

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
Ævar Arnfjörð Bjarmason· Oct 9, 2021, 14:57 UTC · re: René Scharfe · lore

"git reflog expire" blindly trusting timestamps in reflogs

[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...
Show 7 quoted lines
> 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?

Show 31 quoted lines
> 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/
Junio C Hamano· Oct 9, 2021, 17:50 UTC · re: Ævar Arnfjörð Bjarmason · lore

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

Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:
Show 7 quoted lines
> 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.

Jeff King· Oct 11, 2021, 16:32 UTC · re: Ævar Arnfjörð Bjarmason · lore

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

On Sat, Oct 09, 2021 at 04:57:20PM +0200, Ævar Arnfjörð Bjarmason wrote:
Show 12 quoted lines
> 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
Ævar Arnfjörð Bjarmason· Oct 5, 2021, 21:38 UTC · re: Derrick Stolee · lore

Re: p2000 failure due to empty reflog

On Mon, Oct 04 2021, Derrick Stolee wrote:
Show 26 quoted lines
> 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...

René Scharfe· Oct 9, 2021, 14:39 UTC · re: Ævar Arnfjörð Bjarmason · lore

Re: p2000 failure due to empty reflog

Am 05.10.21 um 23:38 schrieb Ævar Arnfjörð Bjarmason:
Show 43 quoted lines
>
> 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é

← back to recent threads