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

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.

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

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

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

On Friday 02 April 2010, Jeff King 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?

Cheers, FJP

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

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

On Saturday 03 April 2010, Jeff King wrote:

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

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

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

[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:

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

Jeff King <peff@peff.net> writes:

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(-)

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

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:

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

Jeff King <peff@peff.net> writes:

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.

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 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.

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

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.

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

Jeff King <peff@peff.net> writes:

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(-)

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(-)

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

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).

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

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

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 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