Extremely slow progress during 'git reflog expire --all'

Extremely slow progress during 'git reflog expire --all'

[Frans Pop]

I wanted to to a 'git gc' on my kernel repo, but that seemed to end in a 
loop: loads of CPU usage, no output. Using 'ps' I found it's not 'git gc' 
itself, but 'git reflog' that's causing the problem.

>From the strace below it does seem like it still makes some progress, but 
I've never had it take anywhere near this long before. Normally it starts 
the count of objects almost immediately.

It's using hardly any memory at all but has one core going flat out.

I'm seeing this with both git 1.6.6.1 and 1.7.0.3 on the same repo.
Environment:
- Debian amd64/Lenny; Core Duo x86_64 2.6.34-rc3 -> 1.6.6.1
- Debian i386/Sid; chroot on the same machine -> 1.7.0.3
I've also tried with 2.6.33 to rule out a kernel issue.

Here's the tail end of an strace I ran. I broke it off after 9+ minutes, 
but I had let it go for longer than that earlier. You can clearly see 
where it starts to "stall" at 21:40:14.

Cheers,
FJP

$ strace -t git reflog expire --all
[...]
21:40:11 open(".git/logs/HEAD.lock", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
21:40:11 open(".git/objects/db/315842dd99ce7fd59697df36185df4b807000a", 
O_RDONLY|O_NOATIME) = 23
21:40:11 fstat(23, {st_mode=S_IFREG|0444, st_size=289, ...}) = 0
21:40:11 mmap(NULL, 289, PROT_READ, MAP_PRIVATE, 23, 0) = 0x7f9b135bb000
21:40:11 close(23)                      = 0
21:40:11 munmap(0x7f9b135bb000, 289)    = 0
21:40:11 open(".git/logs/HEAD", O_RDONLY) = 23
21:40:11 fstat(23, {st_mode=S_IFREG|0644, st_size=171397, ...}) = 0
21:40:11 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x7f9b135bb000
21:40:11 read(23, "bea4c899f2b5fad80099aea979780ef19"..., 4096) = 4096
21:40:11 fstat(4, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
21:40:11 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x7f9b135ba000
21:40:11 read(23, "aca305e8a0209efda740b522024cfdefe"..., 4096) = 4096
21:40:11 read(23, "es\n134a0f063d0c48f08b8731118c4732"..., 4096) = 4096
21:40:12 read(23, "c82b7849a0fe 416c623fe337da58f52a"..., 4096) = 4096
21:40:12 brk(0x2029000)                 = 0x2029000
21:40:12 brk(0x2058000)                 = 0x2058000
21:40:12 brk(0x2080000)                 = 0x2080000
21:40:12 brk(0x20a6000)                 = 0x20a6000
21:40:12 brk(0x20cb000)                 = 0x20cb000
21:40:12 brk(0x20ef000)                 = 0x20ef000
21:40:12 mmap(NULL, 2101248, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x7f9b133b9000
21:40:12 munmap(0x7f9b156a5000, 1052672) = 0
21:40:12 brk(0x2113000)                 = 0x2113000
21:40:12 brk(0x2138000)                 = 0x2138000
21:40:12 brk(0x215c000)                 = 0x215c000
21:40:12 brk(0x217e000)                 = 0x217e000
21:40:12 brk(0x219f000)                 = 0x219f000
21:40:12 brk(0x21c0000)                 = 0x21c0000
21:40:12 brk(0x21e4000)                 = 0x21e4000
21:40:12 brk(0x2208000)                 = 0x2208000
21:40:12 brk(0x222e000)                 = 0x222e000
21:40:12 brk(0x2252000)                 = 0x2252000
21:40:12 brk(0x2275000)                 = 0x2275000
21:40:12 brk(0x2299000)                 = 0x2299000
21:40:12 brk(0x22bf000)                 = 0x22bf000
21:40:12 brk(0x22e3000)                 = 0x22e3000
21:40:12 brk(0x2309000)                 = 0x2309000
21:40:12 brk(0x232f000)                 = 0x232f000
21:40:12 brk(0x2355000)                 = 0x2355000
21:40:12 brk(0x237a000)                 = 0x237a000
21:40:12 brk(0x239e000)                 = 0x239e000
21:40:12 brk(0x23c4000)                 = 0x23c4000
21:40:12 brk(0x23e8000)                 = 0x23e8000
21:40:12 brk(0x240b000)                 = 0x240b000
21:40:12 brk(0x242e000)                 = 0x242e000
21:40:12 brk(0x2454000)                 = 0x2454000
21:40:13 brk(0x2476000)                 = 0x2476000
21:40:13 brk(0x249b000)                 = 0x249b000
21:40:13 brk(0x24c0000)                 = 0x24c0000
21:40:13 brk(0x24e6000)                 = 0x24e6000
21:40:13 brk(0x250b000)                 = 0x250b000
21:40:13 brk(0x2531000)                 = 0x2531000
21:40:13 brk(0x2556000)                 = 0x2556000
21:40:13 brk(0x2578000)                 = 0x2578000
21:40:13 brk(0x259d000)                 = 0x259d000
21:40:13 mmap(NULL, 4198400, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x7f9b12fb8000
21:40:13 munmap(0x7f9b133b9000, 2101248) = 0
21:40:13 brk(0x25c5000)                 = 0x25c5000
21:40:13 brk(0x25ee000)                 = 0x25ee000
21:40:13 brk(0x260f000)                 = 0x260f000
21:40:13 brk(0x2633000)                 = 0x2633000
21:40:13 brk(0x2659000)                 = 0x2659000
21:40:13 brk(0x267e000)                 = 0x267e000
21:40:13 brk(0x26a3000)                 = 0x26a3000
21:40:13 brk(0x26c8000)                 = 0x26c8000
21:40:13 brk(0x26ec000)                 = 0x26ec000
21:40:13 brk(0x2712000)                 = 0x2712000
21:40:13 brk(0x2737000)                 = 0x2737000
21:40:13 brk(0x275b000)                 = 0x275b000
21:40:13 brk(0x2780000)                 = 0x2780000
21:40:13 brk(0x27a6000)                 = 0x27a6000
21:40:13 brk(0x27c9000)                 = 0x27c9000
21:40:13 brk(0x27ec000)                 = 0x27ec000
21:40:13 brk(0x2811000)                 = 0x2811000
21:40:13 brk(0x2839000)                 = 0x2839000
21:40:13 brk(0x285d000)                 = 0x285d000
21:40:13 brk(0x2885000)                 = 0x2885000
21:40:13 brk(0x28ac000)                 = 0x28ac000
21:40:13 brk(0x28d0000)                 = 0x28d0000
21:40:13 brk(0x28f5000)                 = 0x28f5000
21:40:13 brk(0x291f000)                 = 0x291f000
21:40:13 brk(0x2943000)                 = 0x2943000
21:40:14 brk(0x2965000)                 = 0x2965000
21:40:14 brk(0x2988000)                 = 0x2988000
21:40:14 brk(0x29ac000)                 = 0x29ac000
21:40:14 brk(0x29d1000)                 = 0x29d1000
21:40:14 brk(0x29f7000)                 = 0x29f7000
21:40:14 brk(0x2a1b000)                 = 0x2a1b000
21:40:20 brk(0x2a3c000)                 = 0x2a3c000
21:40:35 brk(0x2a5d000)                 = 0x2a5d000
21:40:50 brk(0x2a7e000)                 = 0x2a7e000
21:41:06 brk(0x2a9f000)                 = 0x2a9f000
21:41:22 brk(0x2ac0000)                 = 0x2ac0000
21:41:37 brk(0x2ae1000)                 = 0x2ae1000
21:41:52 brk(0x2b02000)                 = 0x2b02000
21:42:08 brk(0x2b23000)                 = 0x2b23000
21:42:22 brk(0x2b44000)                 = 0x2b44000
21:42:37 brk(0x2b65000)                 = 0x2b65000
21:42:52 brk(0x2b86000)                 = 0x2b86000
21:43:07 brk(0x2ba7000)                 = 0x2ba7000
21:43:22 brk(0x2bc8000)                 = 0x2bc8000
21:43:37 brk(0x2beb000)                 = 0x2beb000
21:43:51 read(23, "ab433be0e8a388d3354bdf15937 Frans"..., 4096) = 4096
21:43:53 brk(0x2c0c000)                 = 0x2c0c000
21:44:04 read(23, "nl> 1265475450 +0100\trebase -i (e"..., 4096) = 4096
21:44:04 read(23, "1265475836 +0100\tcommit: parisc: "..., 4096) = 4096
21:44:05 brk(0x2c2d000)                 = 0x2c2d000
21:44:05 read(23, "0\tcheckout: moving from master to"..., 4096) = 4096
21:44:05 read(23, "c84e745ec814f386ef7f454295ba54d64"..., 4096) = 4096
21:44:05 read(23, "792 1ff647af5425c749e4d625b807d3b"..., 4096) = 4096
21:44:05 brk(0x2c54000)                 = 0x2c54000
21:44:05 brk(0x2c75000)                 = 0x2c75000
21:44:12 brk(0x2c96000)                 = 0x2c96000
21:44:25 brk(0x2cb9000)                 = 0x2cb9000
21:44:37 brk(0x2cda000)                 = 0x2cda000
21:44:50 brk(0x2cfb000)                 = 0x2cfb000
21:45:01 brk(0x2d1c000)                 = 0x2d1c000
21:45:14 brk(0x2d3d000)                 = 0x2d3d000
21:45:26 brk(0x2d5e000)                 = 0x2d5e000
21:45:38 brk(0x2d7f000)                 = 0x2d7f000
21:45:50 brk(0x2da0000)                 = 0x2da0000
21:46:03 brk(0x2dc1000)                 = 0x2dc1000
21:46:14 brk(0x2de2000)                 = 0x2de2000
21:46:27 brk(0x2e03000)                 = 0x2e03000
21:46:39 brk(0x2e24000)                 = 0x2e24000
21:46:51 brk(0x2e45000)                 = 0x2e45000
21:47:03 brk(0x2e66000)                 = 0x2e66000
21:47:15 brk(0x2e87000)                 = 0x2e87000
21:47:27 brk(0x2ea8000)                 = 0x2ea8000
21:47:40 brk(0x2ec9000)                 = 0x2ec9000
21:47:52 brk(0x2eea000)                 = 0x2eea000
21:48:04 brk(0x2f0b000)                 = 0x2f0b000
21:48:17 read(23, "ng HEAD\n8d76bb3b759cba01d3cb9f6ab"..., 4096) = 4096
21:48:17 brk(0x2f2d000)                 = 0x2f2d000
21:48:29 brk(0x2f4e000)                 = 0x2f4e000
21:48:42 brk(0x2f6f000)                 = 0x2f6f000
21:48:53 brk(0x2f90000)                 = 0x2f90000
21:49:05 brk(0x2fb1000)                 = 0x2fb1000
21:49:17 brk(0x2fd2000)                 = 0x2fd2000
21:49:29 brk(0x2ff3000)                 = 0x2ff3000

Re: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Fri, Apr 02, 2010 at 09:54:14PM +0200, Frans Pop wrote:

> I wanted to to a 'git gc' on my kernel repo, but that seemed to end in a 
> loop: loads of CPU usage, no output. Using 'ps' I found it's not 'git gc' 
> itself, but 'git reflog' that's causing the problem.
> 
> From the strace below it does seem like it still makes some progress, but 
> I've never had it take anywhere near this long before. Normally it starts 
> the count of objects almost immediately.
> 
> It's using hardly any memory at all but has one core going flat out.
> 
> I'm seeing this with both git 1.6.6.1 and 1.7.0.3 on the same repo.
> Environment:
> - Debian amd64/Lenny; Core Duo x86_64 2.6.34-rc3 -> 1.6.6.1
> - Debian i386/Sid; chroot on the same machine -> 1.7.0.3
> I've also tried with 2.6.33 to rule out a kernel issue.
> 
> Here's the tail end of an strace I ran. I broke it off after 9+ minutes, 
> but I had let it go for longer than that earlier. You can clearly see 
> where it starts to "stall" at 21:40:14.

FWIW, I have seen this, too, and managed to get an strace snippet that
looked similar to what you saw (mostly memory allocation, and otherwise
chewing on the CPU). I'm guessing there is some O(n^2) loop in there
somewhere. Unfortunately, mine actually completed after a few minutes
and I wasn't able to replicate.

Can you reproduce the problem on your repo? If so, can you possibly tar
it up and make it available (probably just the .git directory would be
enough)?

-Peff

Re: Extremely slow progress during 'git reflog expire --all'

[Frans Pop]

On Friday 02 April 2010, Jeff King wrote:
> Can you reproduce the problem on your repo? If so, can you possibly tar
> it up and make it available (probably just the .git directory would be
> enough)?

Yes, I can reproduce. I've run it a few times and broke it off each time 
before it finished as I really had no idea how much longer it might take.

$ du -sh .git
1008M   .git

I can make that available, but it's going to take a while to upload and I 
don't want to leave it up too long as I'll be abusing a project service 
for that. So the people who want to look at it would have grab it fairly 
promptly (within 2 days or so).

Is that OK?

Cheers,
FJP

Re: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Fri, Apr 02, 2010 at 11:50:19PM +0200, Frans Pop wrote:

> Yes, I can reproduce. I've run it a few times and broke it off each time 
> before it finished as I really had no idea how much longer it might take.
> 
> $ du -sh .git
> 1008M   .git
> 
> I can make that available, but it's going to take a while to upload and I 
> don't want to leave it up too long as I'll be abusing a project service 
> for that. So the people who want to look at it would have grab it fairly 
> promptly (within 2 days or so).
> 
> Is that OK?

That would be fine. If even that is a problem, we can arrange off-list
to get it from you privately and I can stick it somewhere for a week or
two.

-Peff

Re: Extremely slow progress during 'git reflog expire --all'

[Frans Pop]

On Saturday 03 April 2010, Jeff King wrote:
> > I can make that available, but it's going to take a while to upload
> > and I don't want to leave it up too long as I'll be abusing a project
> > service for that. So the people who want to look at it would have grab
> > it fairly promptly (within 2 days or so).

The tarball is up at:
http://alioth.debian.org/~fjp/.tmp/linux-2.6_reflog-issue.tar

Because of the Easter weekend I'll leave it up a bit longer. I plan to 
remove it sometime on Thursday.

Cheers,
FJP

Re: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Sat, Apr 03, 2010 at 04:29:01PM +0200, Frans Pop wrote:

> On Saturday 03 April 2010, Jeff King wrote:
> > > I can make that available, but it's going to take a while to upload
> > > and I don't want to leave it up too long as I'll be abusing a project
> > > service for that. So the people who want to look at it would have grab
> > > it fairly promptly (within 2 days or so).
> 
> The tarball is up at:
> http://alioth.debian.org/~fjp/.tmp/linux-2.6_reflog-issue.tar
> 
> Because of the Easter weekend I'll leave it up a bit longer. I plan to 
> remove it sometime on Thursday.

Thanks, I was able to get it and reproduce your problem. The slowness is
in the expire-unreachable code. You can work around it with:

  git config gc.reflogExpireUnreachable never

Obviously that's not really a fix, but it should let your "git gc" work.

It looks like we do two merge-base calculations for each reflog entry,
which is what takes so long. Perhaps if we know we are going to do a
large number of reachability checks, we can pre-mark all reachable
commits, and then each reflog entry would just need to check the commit
mark.

I don't have any more time now to look at it, but I am cc'ing Junio (who
wrote the original expire-unreachable code) and Shawn (the resident
reflog expert), who may have more input.

-Peff

Re: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

[sorry, resend, I managed to totally screw up Shawn's email in the last
one. Stupid mutt aliases.]

On Sat, Apr 03, 2010 at 04:29:01PM +0200, Frans Pop wrote:

> On Saturday 03 April 2010, Jeff King wrote:
> > > I can make that available, but it's going to take a while to upload
> > > and I don't want to leave it up too long as I'll be abusing a project
> > > service for that. So the people who want to look at it would have grab
> > > it fairly promptly (within 2 days or so).
> 
> The tarball is up at:
> http://alioth.debian.org/~fjp/.tmp/linux-2.6_reflog-issue.tar
> 
> Because of the Easter weekend I'll leave it up a bit longer. I plan to 
> remove it sometime on Thursday.

Thanks, I was able to get it and reproduce your problem. The slowness is
in the expire-unreachable code. You can work around it with:

  git config gc.reflogExpireUnreachable never

Obviously that's not really a fix, but it should let your "git gc" work.

It looks like we do two merge-base calculations for each reflog entry,
which is what takes so long. Perhaps if we know we are going to do a
large number of reachability checks, we can pre-mark all reachable
commits, and then each reflog entry would just need to check the commit
mark.

I don't have any more time now to look at it, but I am cc'ing Junio (who
wrote the original expire-unreachable code) and Shawn (the resident
reflog expert), who may have more input.

-Peff

Re: Extremely slow progress during 'git reflog expire --all'

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> Thanks, I was able to get it and reproduce your problem. The slowness is
> in the expire-unreachable code. You can work around it with:
>
>   git config gc.reflogExpireUnreachable never
>
> Obviously that's not really a fix, but it should let your "git gc" work.
>
> It looks like we do two merge-base calculations for each reflog entry,
> which is what takes so long. Perhaps if we know we are going to do a
> large number of reachability checks, we can pre-mark all reachable
> commits, and then each reflog entry would just need to check the commit
> mark.

Thanks for the analysis, but expire_reflog() that is run for each ref
already does that, I think.  It first runs mark_reachable(), then walks
each reflog entry for the ref to call expire_reflog_ent(), which in turn
calls unreachable() that first checks if mark_reachable() has marked the
commit, and if so we don't run in_merge_bases().

But if the commit in question is not reachable, then we end up running
in_merge_bases() to double-check anyway, which is probably the symptom
that was observed.

So perhaps this is a workable compromise?

 builtin/reflog.c |    7 +++++++
 1 files changed, 7 insertions(+), 0 deletions(-)

diff --git a/builtin/reflog.c b/builtin/reflog.c
index 64e45bd..7e278b8 100644
--- a/builtin/reflog.c
+++ b/builtin/reflog.c
@@ -230,6 +230,13 @@ static int unreachable(struct expire_reflog_cb *cb, struct commit *commit, unsig
 	/* Reachable from the current ref?  Don't prune. */
 	if (commit->object.flags & REACHABLE)
 		return 0;
+	/*
+	 * Unless there was a clock skew, younger ones that are
+	 * reachable should have been marked by mark_reachable().
+	 */
+	if (cb->cmd->expire_total < commit->date)
+		return 1;
+
 	if (in_merge_bases(commit, &cb->ref_commit, 1))
 		return 0;
 

Re: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Sun, Apr 04, 2010 at 11:22:18AM -0700, Junio C Hamano wrote:

> Thanks for the analysis, but expire_reflog() that is run for each ref
> already does that, I think.  It first runs mark_reachable(), then walks
> each reflog entry for the ref to call expire_reflog_ent(), which in turn
> calls unreachable() that first checks if mark_reachable() has marked the
> commit, and if so we don't run in_merge_bases().

Hmm. It looks like mark_reachable() stops traversing when it hits a
commit older than expire_total. I imagine that's to avoid going all the
way to the roots. But if we hit any unreachable entry, in_merge_bases()
is going to have to go all the way to the roots, anyway.

If we just marked everything, couldn't we then trust the REACHABLE
value and not have to do the in_merge_bases double-check? It has worse
best-case cost (since we always go to the root), but better worst-case
(since we can potentially go to the roots for each unreachable reflog
entry).

For example:

> +	/*
> +	 * Unless there was a clock skew, younger ones that are
> +	 * reachable should have been marked by mark_reachable().
> +	 */
> +	if (cb->cmd->expire_total < commit->date)
> +		return 1;
> +
>  	if (in_merge_bases(commit, &cb->ref_commit, 1))
>  		return 0;

If we haven't done a "reflog expire" in a while, won't we have a bunch
of old commits that will still need double-checked, and produce the same
slow behavior? Or is that what your "clock skew" is meant to mean? That
we would have removed those old ones already assuming the commit date
and the reflog entry for them match up? That's not necessarily true if
you move to an older commit, which freshens its reflog entry compared to
the commit date.

I wonder if, in addition to your patch, we should remove the
double-check in_merge_bases and simply report those old ones as
reachable. We may be wrong, but we are erring on the side of keeping
entries, and they will eventually expire in the regular cycle (i.e., 90
days instead of 30).

All of that being said, your patch does drop Frans' case down to about
1s of CPU time, so perhaps it is not worth worrying about beyond that.

-Peff

Re: Extremely slow progress during 'git reflog expire --all'

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> Hmm. It looks like mark_reachable() stops traversing when it hits a
> commit older than expire_total. I imagine that's to avoid going all the
> way to the roots. But if we hit any unreachable entry, in_merge_bases()
> is going to have to go all the way to the roots, anyway.

Yeah, an alternative is to keep the list of commits where the initial
mark_reachable() run stopped, and instead of doing in_merge_bases(),
lazily restart the traversal all the way down to root, and then rely
solely on the REACHABLE bit from then on.

> Or is that what your "clock skew" is meant to mean?

What I meant was you commit A, a child B, rewind clock to commit its child
C at an incorrect and old time, and fix clock to commit its child D which
is at the tip of a ref.  mark_reachable() will stop at C saying that is
sufficiently old and recent A and B may be pruned too early.

> I wonder if, in addition to your patch, we should remove the
> double-check in_merge_bases and simply report those old ones as
> reachable. We may be wrong, but we are erring on the side of keeping
> entries, and they will eventually expire in the regular cycle (i.e., 90
> days instead of 30).
>
> All of that being said, your patch does drop Frans' case down to about
> 1s of CPU time, so perhaps it is not worth worrying about beyond that.

I think a reasonable solution would be along the lines you described, but
the patch you are responding to does err on the wrong side when a clock
skew is there.  Does it matter?  Probably not.

Re: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Mon, Apr 05, 2010 at 11:54:28AM -0700, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> > Hmm. It looks like mark_reachable() stops traversing when it hits a
> > commit older than expire_total. I imagine that's to avoid going all the
> > way to the roots. But if we hit any unreachable entry, in_merge_bases()
> > is going to have to go all the way to the roots, anyway.
> 
> Yeah, an alternative is to keep the list of commits where the initial
> mark_reachable() run stopped, and instead of doing in_merge_bases(),
> lazily restart the traversal all the way down to root, and then rely
> solely on the REACHABLE bit from then on.

Ah, yeah, that is much more clever. It has the same worst case
performance as what I proposed, but is much more optimistic that we
won't have to do it at all.

> > I wonder if, in addition to your patch, we should remove the
> > double-check in_merge_bases and simply report those old ones as
> > reachable. We may be wrong, but we are erring on the side of keeping
> > entries, and they will eventually expire in the regular cycle (i.e., 90
> > days instead of 30).
> >
> > All of that being said, your patch does drop Frans' case down to about
> > 1s of CPU time, so perhaps it is not worth worrying about beyond that.
> 
> I think a reasonable solution would be along the lines you described, but
> the patch you are responding to does err on the wrong side when a clock
> skew is there.  Does it matter?  Probably not.

True. With the technique you mentioned above, you would reverse your
test and do:

  if (flags & REACHABLE)
    return 0;
  if (expanded_reachable_to_root)
    return 1; /* we know it's not */
  expand_reachable_to_root();
  return !(flags & REACHABLE);

I don't think I care enough to do a patch, though. I don't have a
problem with you applying what you posted earlier.

-Peff

Re*: Extremely slow progress during 'git reflog expire --all'

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> True. With the technique you mentioned above, you would reverse your
> test and do:
>
>   if (flags & REACHABLE)
>     return 0;
>   if (expanded_reachable_to_root)
>     return 1; /* we know it's not */
>   expand_reachable_to_root();
>   return !(flags & REACHABLE);
>
> I don't think I care enough to do a patch, though. I don't have a
> problem with you applying what you posted earlier.

Actually I do; I think it breaks correctness a big way (the second
paragraph of the proposed log message of the following).

-- >8 --
Subject: [PATCH] reflog --expire-unreachable: avoid merge-base computation

The option tells the command to expire older reflog entries that refer to
commits that are no longer reachable from the tip of the ref the reflog is
associated with.  To avoid repeated merge_base() invocations, we used to
mark commits that are known to be reachable by walking the history from
the tip until we hit commits that are older than expire-total (which is
the timestamp before which all the reflog entries are expired).

However, it is a different matter if a commit is _not_ known to be
reachable and the commit is known to be unreachable.  Because you can
rewind a ref to an ancient commit and then reset it back to the original
tip, a recent reflog entry can point at a commit that older than the
expire-total timestamp and we shouldn't expire it.  For that reason, we
had to run merge-base computation when a commit is _not_ known to be
reachable.

This introduces a lazy/on-demand traversal of the history to mark
reachable commits in steps.  As before, we mark commits that are newer
than expire-total to optimize the normal case before walking reflog, but
we dig deeper from the commits the initial step left off when we encounter
a commit that is not known to be reachable.

Signed-off-by: Junio C Hamano <gitster@pobox.com>
---

 * By the way, the following diff is extremely hard to read, as for some
   reason "diff" failed to notice that the only change is that we have
   added lines at the beginning of mark_reachable(), modified only the
   latter half of unreachable(), and moved mark_reachable() from after
   unreachable() to before.  Neither "git diff --patience" nor running GNU
   diff on to blobs helps.  Hmph...

 builtin-reflog.c |   96 +++++++++++++++++++++++++++++++----------------------
 1 files changed, 56 insertions(+), 40 deletions(-)

diff --git a/builtin-reflog.c b/builtin-reflog.c
index 7498210..9792090 100644
--- a/builtin-reflog.c
+++ b/builtin-reflog.c
@@ -36,6 +36,8 @@ struct expire_reflog_cb {
 	FILE *newlog;
 	const char *ref;
 	struct commit *ref_commit;
+	struct commit_list *mark_list;
+	unsigned long mark_limit;
 	struct cmd_reflog_expire_cb *cmd;
 	unsigned char last_kept_sha1[20];
 };
@@ -210,46 +212,23 @@ static int keep_entry(struct commit **it, unsigned char *sha1)
 	return 1;
 }
 
-static int unreachable(struct expire_reflog_cb *cb, struct commit *commit, unsigned char *sha1)
+/*
+ * Starting from commits in the cb->mark_list, mark commits that are
+ * reachable from them.  Stop the traversal at commits older than
+ * the expire_limit and queue them back, so that the caller can call
+ * us again to restart the traversal with longer expire_limit.
+ */
+static void mark_reachable(struct expire_reflog_cb *cb)
 {
-	/*
-	 * We may or may not have the commit yet - if not, look it
-	 * up using the supplied sha1.
-	 */
-	if (!commit) {
-		if (is_null_sha1(sha1))
-			return 0;
-
-		commit = lookup_commit_reference_gently(sha1, 1);
-
-		/* Not a commit -- keep it */
-		if (!commit)
-			return 0;
-	}
-
-	/* Reachable from the current ref?  Don't prune. */
-	if (commit->object.flags & REACHABLE)
-		return 0;
-	if (in_merge_bases(commit, &cb->ref_commit, 1))
-		return 0;
-
-	/* We can't reach it - prune it. */
-	return 1;
-}
+	struct commit *commit;
+	struct commit_list *pending;
+	unsigned long expire_limit = cb->mark_limit;
+	struct commit_list *leftover = NULL;
 
-static void mark_reachable(struct commit *commit, unsigned long expire_limit)
-{
-	/*
-	 * We need to compute whether the commit on either side of a reflog
-	 * entry is reachable from the tip of the ref for all entries.
-	 * Mark commits that are reachable from the tip down to the
-	 * time threshold first; we know a commit marked thusly is
-	 * reachable from the tip without running in_merge_bases()
-	 * at all.
-	 */
-	struct commit_list *pending = NULL;
+	for (pending = cb->mark_list; pending; pending = pending->next)
+		pending->item->object.flags &= ~REACHABLE;
 
-	commit_list_insert(commit, &pending);
+	pending = cb->mark_list;
 	while (pending) {
 		struct commit_list *entry = pending;
 		struct commit_list *parent;
@@ -261,8 +240,11 @@ static void mark_reachable(struct commit *commit, unsigned long expire_limit)
 		if (parse_commit(commit))
 			continue;
 		commit->object.flags |= REACHABLE;
-		if (commit->date < expire_limit)
+		if (commit->date < expire_limit) {
+			commit_list_insert(commit, &leftover);
 			continue;
+		}
+		commit->object.flags |= REACHABLE;
 		parent = commit->parents;
 		while (parent) {
 			commit = parent->item;
@@ -272,6 +254,36 @@ static void mark_reachable(struct commit *commit, unsigned long expire_limit)
 			commit_list_insert(commit, &pending);
 		}
 	}
+	cb->mark_list = leftover;
+}
+
+static int unreachable(struct expire_reflog_cb *cb, struct commit *commit, unsigned char *sha1)
+{
+	/*
+	 * We may or may not have the commit yet - if not, look it
+	 * up using the supplied sha1.
+	 */
+	if (!commit) {
+		if (is_null_sha1(sha1))
+			return 0;
+
+		commit = lookup_commit_reference_gently(sha1, 1);
+
+		/* Not a commit -- keep it */
+		if (!commit)
+			return 0;
+	}
+
+	/* Reachable from the current ref?  Don't prune. */
+	if (commit->object.flags & REACHABLE)
+		return 0;
+
+	if (cb->mark_list && cb->mark_limit) {
+		cb->mark_limit = 0; /* dig down to the root */
+		mark_reachable(cb);
+	}
+
+	return !(commit->object.flags & REACHABLE);
 }
 
 static int expire_reflog_ent(unsigned char *osha1, unsigned char *nsha1,
@@ -348,8 +360,12 @@ static int expire_reflog(const char *ref, const unsigned char *sha1, int unused,
 	cb.ref_commit = lookup_commit_reference_gently(sha1, 1);
 	cb.ref = ref;
 	cb.cmd = cmd;
-	if (cb.ref_commit)
-		mark_reachable(cb.ref_commit, cmd->expire_total);
+	if (cb.ref_commit) {
+		cb.mark_list = NULL;
+		commit_list_insert(cb.ref_commit, &cb.mark_list);
+		cb.mark_limit = cmd->expire_total;
+		mark_reachable(&cb);
+	}
 	for_each_reflog_ent(ref, expire_reflog_ent, &cb);
 	if (cb.ref_commit)
 		clear_commit_marks(cb.ref_commit, REACHABLE);
-- 
1.7.1.rc0.212.gbd88f

Re: Re*: Extremely slow progress during 'git reflog expire --all'

[Junio C Hamano]

Side note.

It may be an improvement to dig the history even more incrementally.

Inside unreachable(), we currently dig immediately down to root, but it
may give us a better performance in a long history with reflog entries
that wildly jump everywhere in that history if we dug down to the
timestamp of the commit we are looking at.  A patch to do so on top of the
previous one may look like this.

 builtin-reflog.c |   17 ++++++++++-------
 1 files changed, 10 insertions(+), 7 deletions(-)

diff --git a/builtin-reflog.c b/builtin-reflog.c
index 9792090..42d225f 100644
--- a/builtin-reflog.c
+++ b/builtin-reflog.c
@@ -274,16 +274,19 @@ static int unreachable(struct expire_reflog_cb *cb, struct commit *commit, unsig
 			return 0;
 	}
 
-	/* Reachable from the current ref?  Don't prune. */
-	if (commit->object.flags & REACHABLE)
-		return 0;
+	while (1) {
+		/* Reachable from the current ref?  Don't prune. */
+		if (commit->object.flags & REACHABLE)
+			return 0;
 
-	if (cb->mark_list && cb->mark_limit) {
-		cb->mark_limit = 0; /* dig down to the root */
+		/* Did we mark everything?  Then we know we cannot reach it. */
+		if (!cb->mark_list || !cb->mark_limit)
+			return 1;
+
+		/* Dig down to the timestamp of this commit, or down to root. */
+		cb->mark_limit = (cb->mark_limit < commit->date) ? 0 : commit->date;
 		mark_reachable(cb);
 	}
-
-	return !(commit->object.flags & REACHABLE);
 }
 
 static int expire_reflog_ent(unsigned char *osha1, unsigned char *nsha1,
-- 
1.7.1.rc0.212.gbd88f

Re: Re*: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Wed, Apr 07, 2010 at 11:39:15AM -0700, Junio C Hamano wrote:

> Actually I do; I think it breaks correctness a big way (the second
> paragraph of the proposed log message of the following).
> [...]
> However, it is a different matter if a commit is _not_ known to be
> reachable and the commit is known to be unreachable.  Because you can
> rewind a ref to an ancient commit and then reset it back to the original
> tip, a recent reflog entry can point at a commit that older than the
> expire-total timestamp and we shouldn't expire it.  For that reason, we
> had to run merge-base computation when a commit is _not_ known to be
> reachable.

Oh, right. Didn't I even mention that case earlier in the thread? I was
just being dumb. Or maybe I was pretending to be dumb, so that I could
trick you into writing the patch. Who knows?

> [patch]

Patch looked fine from my reading. I no longer have Frans' gigantic test
repo available, though, so I can't test whether it fixes the problem
(but I'm pretty sure it must from my earlier analysis).

-Peff

Re: Re*: Extremely slow progress during 'git reflog expire --all'

[Jeff King]

On Wed, Apr 07, 2010 at 11:43:22AM -0700, Junio C Hamano wrote:

> Side note.
> 
> It may be an improvement to dig the history even more incrementally.

I doubt it matters much in practice. The important features of the
solution are:

  - for most refs, which are either all-reachable or which don't have
    clock skew, don't go to the roots at all. This is the fast case that
    we should do most of the time.

  - for others, don't go to the roots over and over for each entry. This
    is the slow case, but we just need to make sure it's a not the
    horrible slow case that Frans saw.

Your suggestion speeds up the slow case a little bit, but it is already
acceptably fast. Plus this is an optimistic optimization. There are
still cases where you might have to dig to the roots anyway (e.g.,
whenever you have anything unreachable).

> Inside unreachable(), we currently dig immediately down to root, but it
> may give us a better performance in a long history with reflog entries
> that wildly jump everywhere in that history if we dug down to the
> timestamp of the commit we are looking at.  A patch to do so on top of the
> previous one may look like this.

Why dig to the timestamp? You know you're looking for a particular
commit, so you can dig down to that commit. If it's reachable, stop
there and you have your answer. Any work you do beyond that might be
used for a further entry lookup, but it might not at all. If it's not
reachable, then you're going to end up digging down to the roots anyway.

With an unreachable ref and your scheme, you would just end up not
finding it, extending again, not finding it, extending again, etc. But
you can never be sure it's truly unreachable without going to the roots
or assuming no clock skew, so that is what we'll end up doing.

-Peff