{"thread":{"id":"46335","subject":"Fetching new refs gets progressively slower","startedAt":"2017-07-09T10:25:15Z","lastAt":"2017-08-17T21:38:04Z","messageCount":6,"participants":["s@kazlauskas.me","Jeff King","Michael Haggerty","Brandon Williams","Junio C Hamano"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"324020","messageId":"20170709102506.GA32425@kumabox","threadId":"46335","inReplyTo":null,"subject":"Fetching new refs gets progressively slower","fromName":"","fromEmail":"s@kazlauskas.me","sentAt":"2017-07-09T10:25:06Z","receivedAt":"2017-07-09T10:25:15Z","isPatch":false,"sender":{"key":"s@kazlauskas.me","avatar":null},"body":"I have a weird issue where fetching a large number of refs will start off with \nlines like these:\n\n* [new ref]               refs/pull/10000/head -> origin/pr/10000\n* [new ref]               refs/pull/10001/head -> origin/pr/10001\n\ngoing fairly fast, and then progressively getting slower and slower. By the time \ngit is working on 40 thousandth such ref, it seems like it is only handling \nabout 3-5 such “new ref”s.\n\nThese are the steps I used to reproduce:\n\n $ git clone git@github.com:rust-lang/rust\n $ # edit .git/config to add \n $ # `fetch = +refs/pull/*/head:refs/remotes/origin/pr/*` under origin remote\n $ git fetch\n\nI tried this on three distinct file systems: zfs, ext4 and tmpfs, and on two \ndistinct systems (both with different SSDs in it). Both exhibit the \napproximately the same behaviour. Both on a fairly recent version of Linux.\n\nHere’s some timings:\n\nSystem 1 (ext4) 97% (1047.74 real, 700.11 kernel, 319.89 user); 599476k resident\nSystem 1 (tmpf) 97% (963.78 real, 647.51 kernel, 292.77 user); 600052k resident\nSystem 1 (zfs) 98% (2116.66 real, 1715.86 kernel, 370.32 user); 531232k resident\nSystem 2 (ext4) 97% (1036.56 real, 710.54 kernel, 300.81 user); 602160k resident\n\nGit version is same on both systems: 2.13.1\n\nI did not investigate the issue more throughoutly, but I suspect that git will \nend up doing something resembling listing the contents of the directory of refs \nfor each “new ref” it is creating.\n\nS.\n"},{"id":"324022","messageId":"20170709112932.njac5m6jmgmjywoz@sigill.intra.peff.net","threadId":"46335","inReplyTo":"20170709102506.GA32425@kumabox","subject":"Re: Fetching new refs gets progressively slower","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-07-09T11:29:32Z","receivedAt":"2017-07-09T11:29:39Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Jul 09, 2017 at 01:25:06PM +0300, s@kazlauskas.me wrote:\n\n> I have a weird issue where fetching a large number of refs will start off\n> with lines like these:\n> \n> * [new ref]               refs/pull/10000/head -> origin/pr/10000\n> * [new ref]               refs/pull/10001/head -> origin/pr/10001\n> \n> going fairly fast, and then progressively getting slower and slower. By the\n> time git is working on 40 thousandth such ref, it seems like it is only\n> handling about 3-5 such “new ref”s.\n> \n> These are the steps I used to reproduce:\n> \n> $ git clone git@github.com:rust-lang/rust\n> $ # edit .git/config to add $ # `fetch =\n> +refs/pull/*/head:refs/remotes/origin/pr/*` under origin remote\n> $ git fetch\n\nInteresting. The CPU is definitely going to user-space, and it does look\nlike a quadratic case, where we end up re-reading the loose ref\ndirectory for each new ref we write.\n\nThe backtrace looks something like:\n\n  #1  0x0000555d86bcaf62 in files_read_raw_ref (ref_store=0x555d88d63a60, \n      refname=0x555d8a4791b0 \"refs/remotes/origin/pr/10936\", \n      sha1=0x7ffd29cbe1a0 \"\\003ŕX[\\212*\\037\\064xE\\fU\\362!z44!<]U\", referent=0x555d86efc630 <sb_refname>, \n      type=0x7ffd29cbe0c4) at refs/files-backend.c:686\n  #2  0x0000555d86bc845f in refs_read_raw_ref (ref_store=0x555d88d63a60, \n      refname=0x555d8a4791b0 \"refs/remotes/origin/pr/10936\", \n      sha1=0x7ffd29cbe1a0 \"\\003ŕX[\\212*\\037\\064xE\\fU\\362!z44!<]U\", referent=0x555d86efc630 <sb_refname>, \n      type=0x7ffd29cbe0c4) at refs.c:1391\n  #3  0x0000555d86bc851f in refs_resolve_ref_unsafe (refs=0x555d88d63a60, \n      refname=0x555d8a4791b0 \"refs/remotes/origin/pr/10936\", resolve_flags=1, \n      sha1=0x7ffd29cbe1a0 \"\\003ŕX[\\212*\\037\\064xE\\fU\\362!z44!<]U\", flags=0x7ffd29cbe19c) at refs.c:1430\n  #4  0x0000555d86bca9de in loose_fill_ref_dir (ref_store=0x555d88d63a60, dir=0x555d8a478cc8, \n      dirname=0x555d8a478cf0 \"refs/remotes/origin/pr/\") at refs/files-backend.c:485\n  #5  0x0000555d86bd1444 in get_ref_dir (entry=0x555d8a478cc0) at refs/ref-cache.c:28\n  #6  0x0000555d86bd18d4 in search_for_subdir (dir=0x555d8a478c78, \n      subdirname=0x555d8a414330 \"refs/remotes/origin/pr/13832/\", len=23, mkdir=0) at refs/ref-cache.c:172\n  #7  0x0000555d86bd192d in find_containing_dir (dir=0x555d8a478c78, \n      refname=0x555d8a414330 \"refs/remotes/origin/pr/13832/\", mkdir=0) at refs/ref-cache.c:191\n  #8  0x0000555d86bd23a4 in cache_ref_iterator_begin (cache=0x555d8a418380, \n      prefix=0x555d8a414330 \"refs/remotes/origin/pr/13832/\", prime_dir=1) at refs/ref-cache.c:567\n  #9  0x0000555d86bcb8eb in files_ref_iterator_begin (ref_store=0x555d88d63a60, \n      prefix=0x555d8a414330 \"refs/remotes/origin/pr/13832/\", flags=1) at refs/files-backend.c:1120\n  #10 0x0000555d86bc801a in refs_ref_iterator_begin (refs=0x555d88d63a60, \n      prefix=0x555d8a414330 \"refs/remotes/origin/pr/13832/\", trim=0, flags=1) at refs.c:1268\n  #11 0x0000555d86bc9289 in refs_verify_refname_available (refs=0x555d88d63a60, \n      refname=0x555d88d64b50 \"refs/remotes/origin/pr/13832\", extras=0x7ffd29cbe620, skip=0x0, err=0x7ffd29cbe710)\n      at refs.c:1887\n  #12 0x0000555d86bcb553 in lock_raw_ref (refs=0x555d88d63a60, refname=0x555d88d64b50 \"refs/remotes/origin/pr/13832\", \n      mustexist=0, extras=0x7ffd29cbe620, skip=0x0, lock_p=0x7ffd29cbe588, referent=0x7ffd29cbe590, \n      type=0x555d88d64b38, err=0x7ffd29cbe710) at refs/files-backend.c:956\n  #13 0x0000555d86bcf1bc in lock_ref_for_update (refs=0x555d88d63a60, update=0x555d88d64b00, \n      transaction=0x555d88d64d20, head_ref=0x555d8a435630 \"refs/heads/master\", affected_refnames=0x7ffd29cbe620, \n      err=0x7ffd29cbe710) at refs/files-backend.c:2764\n\nThe issue seems recent. Bisecting leads to Michael's 524a9fdb5\n(refs_verify_refname_available(): use function in more places,\n2017-04-16), which makes sense.\n\n-Peff\n"},{"id":"326605","messageId":"4e81f1ecf190082d3415d96650014841cd4c5b19.1502982012.git.mhagger@alum.mit.edu","threadId":"46335","inReplyTo":"20170709112932.njac5m6jmgmjywoz@sigill.intra.peff.net","subject":"[PATCH] files-backend: cheapen refname_available check when locking refs","fromName":"Michael Haggerty","fromEmail":"mhagger@alum.mit.edu","sentAt":"2017-08-17T15:12:50Z","receivedAt":"2017-08-17T15:13:04Z","isPatch":true,"sender":{"key":"mhagger@alum.mit.edu","avatar":"https://avatars.githubusercontent.com/u/119718?v=4"},"body":"When locking references in preparation for updating them, we need to\ncheck that none of the newly added references D/F conflict with\nexisting references (e.g., we don't allow `refs/foo` to be added if\n`refs/foo/bar` already exists, or vice versa).\n\nPrior to 524a9fdb51 (refs_verify_refname_available(): use function in\nmore places, 2017-04-16), conflicts with existing loose references\nwere checked by looking directly in the filesystem, and then conflicts\nwith existing packed references were checked by running\n`verify_refname_available_dir()` against the packed-refs cache.\n\nBut that commit changed the final check to call\n`refs_verify_refname_available()` against the *whole* files ref-store,\nincluding both loose and packed references, with the following\ncomment:\n\n> This means that those callsites now check for conflicts with all\n> references rather than just packed refs, but the performance cost\n> shouldn't be significant (and will be regained later).\n\nThat comment turned out to be too sanguine. User s@kazlauskas.me\nreported that fetches involving a very large number of references in\nneighboring directories were slowed down by that change.\n\nThe problem is that when fetching, each reference is updated\nindividually, within its own reference transaction. This is done\nbecause some reference updates might succeed even though others fail.\nBut every time a reference update transaction is finished,\n`clear_loose_ref_cache()` is called. So when it is time to update the\nnext reference, part of the loose ref cache has to be repopulated for\nthe `refs_verify_refname_available()` call. If the references are all\nin neighboring directories, then the cost of repopulating the\nreference cache increases with the number of references, resulting in\nO(N²) effort.\n\nThe comment above also claims that the performance cost \"will be\nregained later\". The idea was that once the packed-refs were finished\nbeing split out into a separate ref-store, we could limit the\n`refs_verify_refname_available()` call to the packed references again.\nThat is what we do now.\n\nSigned-off-by: Michael Haggerty <mhagger@alum.mit.edu>\n---\nThis patch applies on top of branch mh/packed-ref-store. It can also\nbe obtained from my fork [1] as branch \"faster-refname-available-check\".\n\nI was testing this using the reporter's recipe (but fetching from a\nlocal clone), and found the following surprising timing numbers:\n\nb05855b5bc (before the slowdown): 22.7 s\n524a9fdb51 (immediately after the slowdown): 13 minutes\n4e81f1ecf1 (after this fix): 14.5 s\n\nThe fact that the fetch is now significantly *faster* than before the\nslowdown seems not to have anything to do with the reference code.\n\n refs/files-backend.c | 8 ++++----\n 1 file changed, 4 insertions(+), 4 deletions(-)\n\ndiff --git a/refs/files-backend.c b/refs/files-backend.c\nindex e9b95592b6..f2a420c611 100644\n--- a/refs/files-backend.c\n+++ b/refs/files-backend.c\n@@ -631,11 +631,11 @@ static int lock_raw_ref(struct files_ref_store *refs,\n \n \t\t/*\n \t\t * If the ref did not exist and we are creating it,\n-\t\t * make sure there is no existing ref that conflicts\n-\t\t * with refname:\n+\t\t * make sure there is no existing packed ref that\n+\t\t * conflicts with refname:\n \t\t */\n \t\tif (refs_verify_refname_available(\n-\t\t\t\t    &refs->base, refname,\n+\t\t\t\t    refs->packed_ref_store, refname,\n \t\t\t\t    extras, skip, err))\n \t\t\tgoto error_return;\n \t}\n@@ -938,7 +938,7 @@ static struct ref_lock *lock_ref_sha1_basic(struct files_ref_store *refs,\n \t * our refname.\n \t */\n \tif (is_null_oid(&lock->old_oid) &&\n-\t    refs_verify_refname_available(&refs->base, refname,\n+\t    refs_verify_refname_available(refs->packed_ref_store, refname,\n \t\t\t\t\t  extras, skip, err)) {\n \t\tlast_errno = ENOTDIR;\n \t\tgoto error_return;\n-- \n2.11.0\n\n"},{"id":"326606","messageId":"20170817152240.coioktoqfkcvxldj@sigill.intra.peff.net","threadId":"46335","inReplyTo":"4e81f1ecf190082d3415d96650014841cd4c5b19.1502982012.git.mhagger@alum.mit.edu","subject":"Re: [PATCH] files-backend: cheapen refname_available check when locking refs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-08-17T15:22:40Z","receivedAt":"2017-08-17T15:22:59Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Aug 17, 2017 at 05:12:50PM +0200, Michael Haggerty wrote:\n\n> I was testing this using the reporter's recipe (but fetching from a\n> local clone), and found the following surprising timing numbers:\n> \n> b05855b5bc (before the slowdown): 22.7 s\n> 524a9fdb51 (immediately after the slowdown): 13 minutes\n> 4e81f1ecf1 (after this fix): 14.5 s\n> \n> The fact that the fetch is now significantly *faster* than before the\n> slowdown seems not to have anything to do with the reference code.\n\nI bisected this (with some hackery, since the commits in the middle all\ntake 13 minutes to run). The other speedup is indeed unrelated, and is\ndue to Brandon's aacc5c1a81 (submodule: refactor logic to determine\nchanged submodules, 2017-05-01).\n\nThe commit message doesn't mention performance (it's mostly about code\nreduction). I think the speedup comes from using\ndiff_tree_combined_merge() instead of manually diffing each commit\nagainst its parents. But I didn't do further timings to verify that (I'm\nreporting it here mostly as an interesting curiosity for submodule\nfolks).\n\n> diff --git a/refs/files-backend.c b/refs/files-backend.c\n> index e9b95592b6..f2a420c611 100644\n> --- a/refs/files-backend.c\n> +++ b/refs/files-backend.c\n> @@ -631,11 +631,11 @@ static int lock_raw_ref(struct files_ref_store *refs,\n>  \n>  \t\t/*\n>  \t\t * If the ref did not exist and we are creating it,\n> -\t\t * make sure there is no existing ref that conflicts\n> -\t\t * with refname:\n> +\t\t * make sure there is no existing packed ref that\n> +\t\t * conflicts with refname:\n>  \t\t */\n>  \t\tif (refs_verify_refname_available(\n> -\t\t\t\t    &refs->base, refname,\n> +\t\t\t\t    refs->packed_ref_store, refname,\n>  \t\t\t\t    extras, skip, err))\n>  \t\t\tgoto error_return;\n>  \t}\n\nThis seems too easy to be true. :) But I think it matches what we were\ndoing before 524a9fdb51 (so it's correct), and the performance numbers\ndon't lie.\n\n-Peff\n"},{"id":"326619","messageId":"20170817175652.GB109680@google.com","threadId":"46335","inReplyTo":"20170817152240.coioktoqfkcvxldj@sigill.intra.peff.net","subject":"Re: [PATCH] files-backend: cheapen refname_available check when locking refs","fromName":"Brandon Williams","fromEmail":"bmwill@google.com","sentAt":"2017-08-17T17:56:52Z","receivedAt":"2017-08-17T17:56:59Z","isPatch":true,"sender":{"key":"bwilliams.eng@gmail.com","avatar":null},"body":"On 08/17, Jeff King wrote:\n> On Thu, Aug 17, 2017 at 05:12:50PM +0200, Michael Haggerty wrote:\n> \n> > I was testing this using the reporter's recipe (but fetching from a\n> > local clone), and found the following surprising timing numbers:\n> > \n> > b05855b5bc (before the slowdown): 22.7 s\n> > 524a9fdb51 (immediately after the slowdown): 13 minutes\n> > 4e81f1ecf1 (after this fix): 14.5 s\n> > \n> > The fact that the fetch is now significantly *faster* than before the\n> > slowdown seems not to have anything to do with the reference code.\n> \n> I bisected this (with some hackery, since the commits in the middle all\n> take 13 minutes to run). The other speedup is indeed unrelated, and is\n> due to Brandon's aacc5c1a81 (submodule: refactor logic to determine\n> changed submodules, 2017-05-01).\n> \n> The commit message doesn't mention performance (it's mostly about code\n> reduction). I think the speedup comes from using\n> diff_tree_combined_merge() instead of manually diffing each commit\n> against its parents. But I didn't do further timings to verify that (I'm\n> reporting it here mostly as an interesting curiosity for submodule\n> folks).\n\nHaha always great to see an unintended improvement in performance!  Yeah\nthat commit was mostly about removing duplicate code but I'm glad that\nit ended up being a benefit to perf too.\n\n> \n> > diff --git a/refs/files-backend.c b/refs/files-backend.c\n> > index e9b95592b6..f2a420c611 100644\n> > --- a/refs/files-backend.c\n> > +++ b/refs/files-backend.c\n> > @@ -631,11 +631,11 @@ static int lock_raw_ref(struct files_ref_store *refs,\n> >  \n> >  \t\t/*\n> >  \t\t * If the ref did not exist and we are creating it,\n> > -\t\t * make sure there is no existing ref that conflicts\n> > -\t\t * with refname:\n> > +\t\t * make sure there is no existing packed ref that\n> > +\t\t * conflicts with refname:\n> >  \t\t */\n> >  \t\tif (refs_verify_refname_available(\n> > -\t\t\t\t    &refs->base, refname,\n> > +\t\t\t\t    refs->packed_ref_store, refname,\n> >  \t\t\t\t    extras, skip, err))\n> >  \t\t\tgoto error_return;\n> >  \t}\n> \n> This seems too easy to be true. :) But I think it matches what we were\n> doing before 524a9fdb51 (so it's correct), and the performance numbers\n> don't lie.\n> \n> -Peff\n\n-- \nBrandon Williams\n"},{"id":"326648","messageId":"xmqqtw15euz4.fsf@gitster.mtv.corp.google.com","threadId":"46335","inReplyTo":"20170817152240.coioktoqfkcvxldj@sigill.intra.peff.net","subject":"Re: [PATCH] files-backend: cheapen refname_available check when locking refs","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-08-17T21:37:51Z","receivedAt":"2017-08-17T21:38:04Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n>> diff --git a/refs/files-backend.c b/refs/files-backend.c\n>> index e9b95592b6..f2a420c611 100644\n>> --- a/refs/files-backend.c\n>> +++ b/refs/files-backend.c\n>> @@ -631,11 +631,11 @@ static int lock_raw_ref(struct files_ref_store *refs,\n>>  \n>>  \t\t/*\n>>  \t\t * If the ref did not exist and we are creating it,\n>> -\t\t * make sure there is no existing ref that conflicts\n>> -\t\t * with refname:\n>> +\t\t * make sure there is no existing packed ref that\n>> +\t\t * conflicts with refname:\n>>  \t\t */\n>>  \t\tif (refs_verify_refname_available(\n>> -\t\t\t\t    &refs->base, refname,\n>> +\t\t\t\t    refs->packed_ref_store, refname,\n>>  \t\t\t\t    extras, skip, err))\n>>  \t\t\tgoto error_return;\n>>  \t}\n>\n> This seems too easy to be true. :) But I think it matches what we were\n> doing before 524a9fdb51 (so it's correct), and the performance numbers\n> don't lie.\n\nThanks, all.  The log message explained the change very well, even\nthough I agree that the patch text does indeed look too easy to be\ntrue ;-).\n\nWill queue.\n"}]}