Re: [PATCH v2 29/33] refs: resolve symbolic refs first

From: Jeff King <peff@peff.net>
Date: May 12, 2016, 07:45 UTC
Message-ID: <20160512074528.GB10922@sigill.intra.peff.net>
In-Reply-To: <66d33af21bd1e398973414435af43d06f2e2099c.1462550456.git.mhagger@alum.mit.edu>

On Fri, May 06, 2016 at 06:14:10PM +0200, Michael Haggerty wrote:

> This makes use of a new function, lock_ref_raw(), which is analogous to
> read_ref_raw(), but acquires a lock on the reference before reading it.

Minor nit: the new function is actually called lock_raw_ref(). I don't care which is used, just an inconsistency.

But my much bigger (non-)nit is that this seems to make large ref updates much slower. You can see this by running t5551 with "--long". In t5551.26, we fetch 48000 new tags into a repository that already has 2000 tags. Before this patch, it takes about 2 seconds. After, it chews CPU for several minutes (I never actually let it finish).

The perf output isn't all that instructive. We seem to spend a lot of time reading directory entries. Attaching with gdb shows:

#0  0x00007f35e00c2670 in __open_nocancel () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000000533982 in read_raw_ref (
    refname=0x4e899f0 "refs/tags/blablablablablablablablablablablablablablablablablablablablablablablablablablablablablabla-11520", sha1=0x7fff7c5aff30 "\002\357\373\070\332{\341\005\366츖\265G\276\332\f\025\271\276\377\177", 
    referent=0x836300 <sb_refname>, type=0x7fff7c5afe34) at refs/files-backend.c:1468
#2  0x0000000000530bf3 in resolve_ref_unsafe (
    refname=0x4e899f0 "refs/tags/blablablablablablablablablablablablablablablablablablablablablablablablablablablablablabla-11520", resolve_flags=1, 
    sha1=0x7fff7c5aff30 "\002\357\373\070\332{\341\005\366츖\265G\276\332\f\025\271\276\377\177", 
    flags=0x7fff7c5aff2c) at refs.c:1209
#3  0x000000000052e56f in read_ref_full (
    refname=0x4e899f0 "refs/tags/blablablablablablablablablablablablablablablablablablablablablablablablablablablablablabla-11520", resolve_flags=1, 
    sha1=0x7fff7c5aff30 "\002\357\373\070\332{\341\005\366츖\265G\276\332\f\025\271\276\377\177", 
    flags=0x7fff7c5aff2c) at refs.c:169
#4  0x000000000053316e in read_loose_refs (dirname=0x4e30f80 "refs/tags/", dir=0x4e30f58) at refs/files-backend.c:1216
#5  0x0000000000531435 in get_ref_dir (entry=0x4e30f50) at refs/files-backend.c:174
#6  0x000000000053265c in verify_refname_available_dir (
    refname=0x1cd9438 "refs/tags/blablablablablablablablablablablablablablablablablablablablablablablablablablablablablabla-12016", extras=0x7fff7c5b01d0, skip=0x0, dir=0x4dd6e98, err=0x7fff7c5b02a0) at refs/files-backend.c:789
#7  0x0000000000533e44 in lock_raw_ref (
    refname=0x1cd9438 "refs/tags/blablablablablablablablablablablablablablablablablablablablablablablablablablablablablabla-12016", mustexist=0, extras=0x7fff7c5b01d0, skip=0x0, lock_p=0x1cd9420, referent=0x7fff7c5b0140, type=0x1cd9428, 
    err=0x7fff7c5b02a0) at refs/files-backend.c:1663
#8  0x00000000005379d7 in lock_ref_for_update (update=0x1cd93f0, transaction=0x4db0150, 
    head_ref=0x4db0000 "refs/heads/master", affected_refnames=0x7fff7c5b01d0, err=0x7fff7c5b02a0)
    at refs/files-backend.c:3416
[...]

So I'd expect us to hit that lock_ref_for_update() for each of the new refs. But then we end up in verify_refname_available_dir(), which wants to read all of the loose refs again. So we end up with a quadratic number of calls to read_ref_full().

I haven't found the actual bug yet. It may be something as simple as not clearing REF_INCOMPLETE from the loose-ref cache when we ought to. But that's a wild (optimistic) guess.

-Peff