{"thread":{"id":"44292","subject":"Huge performance bottleneck reading packs","startedAt":"2016-10-12T22:31:39Z","lastAt":"2016-10-18T10:28:21Z","messageCount":22,"participants":["Vegard Nossum","Junio C Hamano","Jeff King","Jakub Narębski"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"304039","messageId":"ea8db41f-2ea4-b37b-e6f8-1f1d428aea5d@oracle.com","threadId":"44292","inReplyTo":null,"subject":"Huge performance bottleneck reading packs","fromName":"Vegard Nossum","fromEmail":"vegard.nossum@oracle.com","sentAt":"2016-10-12T22:30:52Z","receivedAt":"2016-10-12T22:31:39Z","isPatch":false,"sender":{"key":"vegard.nossum@oracle.com","avatar":"https://avatars.githubusercontent.com/u/24173?v=4"},"body":"Hi all,\n\nI've bisected a performance regression (noticed by Quentin and myself)\nwhich caused a 'git fetch' to go from ~1m30s to ~2m40s:\n\ncommit 47bf4b0fc52f3ad5823185a85f5f82325787c84b\nAuthor: Jeff King \nDate: Mon Jun 30 13:04:03 2014 -0400\n\n prepare_packed_git_one: refactor duplicate-pack check\n\nReverting this commit from a recent mainline master brings the time back\ndown from ~2m24s to ~1m19s.\n\nThe bisect log:\n\nv2.8.1 -- 2m41s, 2m50s (bad)\nv1.9.0 -- 1m39s, 1m46s (good)\n\n2.3.4.312.gea1fd48 -- 2m40s\n2.1.0.18.gc285171 -- 2m42s\n2.0.0.140.g6753d8a -- 1m27s\n2.0.1.480.g60e2f5a -- 1m34s\n2.0.2.631.gad25da0 -- 2m39s\n2.0.1.565.ge0a064a -- 1m30s\n2.0.1.622.g2e42338 -- 2m29s\n2.0.0.rc1.32.g5165dd5 -- 1m30s\n2.0.1.607.g5418212 -- 1m32s\n2.0.1.7.g6dda4e6 -- 1m28s\n2.0.1.619.g6e40947 -- 2m25s\n2.0.1.9.g47bf4b0 -- 2m18s\n2.0.1.8.gd6cd00c -- 1m36.542s\n\nHowever, the commit found by 'git blame' above appears just fine to me,\nI haven't been able to spot a bug in it.\n\nA closer inspection reveals the problem to really be that this is an\nextremely hot path with more than -- holy cow -- 4,106,756,451\niterations on the 'packed_git' list for a single 'git fetch' on my\nrepository. I'm guessing the patch above just made the inner loop\never so slightly slower.\n\nMy .git/objects/pack/ has ~2088 files (1042 idx files, 1042 pack files,\nand 4 tmp_pack_* files).\n\nI am convinced that it is not necessary to rescan the entire pack\ndirectory 11,348 times or do all 4 _BILLION_ memcmp() calls for a single\n'git fetch', even for a large repository like mine.\n\nI could try to write a patch to reduce the number of times we rescan the\npack directory. However, I've never even looked at the file before\ntoday, so any hints regarding what would need to be done would be\nappreciated.\n\nThanks,\n\n(Cced some people with changes in the area.)\n\n\nVegard\n"},{"id":"304041","messageId":"xmqqpon5190s.fsf@gitster.mtv.corp.google.com","threadId":"44292","inReplyTo":"ea8db41f-2ea4-b37b-e6f8-1f1d428aea5d@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2016-10-12T22:45:39Z","receivedAt":"2016-10-12T22:45:48Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Vegard Nossum writes:\n\n> A closer inspection reveals the problem to really be that this is an\n> extremely hot path with more than -- holy cow -- 4,106,756,451\n> iterations on the 'packed_git' list for a single 'git fetch' on my\n> repository. I'm guessing the patch above just made the inner loop\n> ever so slightly slower.\n\nVery plausible, and this ...\n\n> My .git/objects/pack/ has ~2088 files (1042 idx files, 1042 pack files,\n> and 4 tmp_pack_* files).\n\n... may explain why nobody else has seen a difference. \n\nIs there a reason why your repository has that many pack files? Is\nautomatic GC not working for some reason?\n\n\"gc\" would try to make sure that you have reasonably low number of\npacks, as having too many packs is detrimental for performance for\nmultiple reasons, including:\n\n * All objects in a single pack expressed in delta format (i.e. only\n the difference from another object is stored) must eventually\n have another object that its difference is based on recorded in\n the full format in the same packfile.\n\n * A single packfile records a single object only once, but it is\n normal (and often required because of the point above) that the\n same object appears in multiple packfiles.\n\n * Locating of objects from a single packfile uses its .idx file by\n binary search of sorted list of object names, which is efficient,\n but this cost is multiplied linearly as the number of packs you\n have in your repository.\n\n"},{"id":"304043","messageId":"20161012230143.5kxcmtityaasra5j@sigill.intra.peff.net","threadId":"44292","inReplyTo":"ea8db41f-2ea4-b37b-e6f8-1f1d428aea5d@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-12T23:01:43Z","receivedAt":"2016-10-12T23:02:34Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 13, 2016 at 12:30:52AM +0200, Vegard Nossum wrote:\n\n> However, the commit found by 'git blame' above appears just fine to me,\n> I haven't been able to spot a bug in it.\n> \n> A closer inspection reveals the problem to really be that this is an\n> extremely hot path with more than -- holy cow -- 4,106,756,451\n> iterations on the 'packed_git' list for a single 'git fetch' on my\n> repository. I'm guessing the patch above just made the inner loop\n> ever so slightly slower.\n> \n> My .git/objects/pack/ has ~2088 files (1042 idx files, 1042 pack files,\n> and 4 tmp_pack_* files).\n\nYeah. I agree that the commit you found makes the check a little more\nexpensive, but I think the root of the problem is calling\nprepare_packed_git_one many times. This _should_ happen once for each\npack at program startup, and possibly again if we need to re-scan the\npack directory to account for racing with a simultaneous repack.\n\nThe latter is generally triggered when we fail to look up an object we\nexpect to exist. So I'd suspect 45e8a74 (has_sha1_file: re-check pack\ndirectory before giving up, 2013-08-30) is playing a part. We dealt with\nthat to some degree in 0eeb077 (index-pack: avoid excessive re-reading\nof pack directory, 2015-06-09), but it would not surprise me if there is\nanother spot that needs similar treatment.\n\nDoes the patch below help?\n\ndiff --git a/builtin/fetch.c b/builtin/fetch.c\nindex d5329f9..c0f3c2c 100644\n--- a/builtin/fetch.c\n+++ b/builtin/fetch.c\n@@ -243,7 +243,7 @@ static void find_non_local_tags(struct transport *transport,\n \t\tif (ends_with(ref->name, \"^{}\")) {\n \t\t\tif (item && !has_object_file(&ref->old_oid) &&\n \t\t\t !will_fetch(head, ref->old_oid.hash) &&\n-\t\t\t !has_sha1_file(item->util) &&\n+\t\t\t !has_sha1_file_with_flags(item->util, HAS_SHA1_QUICK) &&\n \t\t\t !will_fetch(head, item->util))\n \t\t\t\titem->util = NULL;\n \t\t\titem = NULL;\n@@ -256,7 +256,8 @@ static void find_non_local_tags(struct transport *transport,\n \t\t * to check if it is a lightweight tag that we want to\n \t\t * fetch.\n \t\t */\n-\t\tif (item && !has_sha1_file(item->util) &&\n+\t\tif (item &&\n+\t\t !has_sha1_file_with_flags(item->util, HAS_SHA1_QUICK) &&\n \t\t !will_fetch(head, item->util))\n \t\t\titem->util = NULL;\n \n@@ -276,7 +277,8 @@ static void find_non_local_tags(struct transport *transport,\n \t * We may have a final lightweight tag that needs to be\n \t * checked to see if it needs fetching.\n \t */\n-\tif (item && !has_sha1_file(item->util) &&\n+\tif (item &&\n+\t !has_sha1_file_with_flags(item->util, HAS_SHA1_QUICK) &&\n \t !will_fetch(head, item->util))\n \t\titem->util = NULL;\n \n\n-Peff\n"},{"id":"304046","messageId":"20161012231807.syockv2emrsjf55r@sigill.intra.peff.net","threadId":"44292","inReplyTo":"20161012230143.5kxcmtityaasra5j@sigill.intra.peff.net","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-12T23:18:07Z","receivedAt":"2016-10-12T23:24:55Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Oct 12, 2016 at 07:01:43PM -0400, Jeff King wrote:\n\n> On Thu, Oct 13, 2016 at 12:30:52AM +0200, Vegard Nossum wrote:\n> \n> > However, the commit found by 'git blame' above appears just fine to me,\n> > I haven't been able to spot a bug in it.\n> > \n> > A closer inspection reveals the problem to really be that this is an\n> > extremely hot path with more than -- holy cow -- 4,106,756,451\n> > iterations on the 'packed_git' list for a single 'git fetch' on my\n> > repository. I'm guessing the patch above just made the inner loop\n> > ever so slightly slower.\n> > \n> > My .git/objects/pack/ has ~2088 files (1042 idx files, 1042 pack files,\n> > and 4 tmp_pack_* files).\n> \n> Yeah. I agree that the commit you found makes the check a little more\n> expensive, but I think the root of the problem is calling\n> prepare_packed_git_one many times. This _should_ happen once for each\n> pack at program startup, and possibly again if we need to re-scan the\n> pack directory to account for racing with a simultaneous repack.\n> \n> The latter is generally triggered when we fail to look up an object we\n> expect to exist. So I'd suspect 45e8a74 (has_sha1_file: re-check pack\n> directory before giving up, 2013-08-30) is playing a part. We dealt with\n> that to some degree in 0eeb077 (index-pack: avoid excessive re-reading\n> of pack directory, 2015-06-09), but it would not surprise me if there is\n> another spot that needs similar treatment.\n> \n> Does the patch below help?\n\nAlso, is it possible to make the repository in question available? I\nmight be able to reproduce based on your description, but it would save\ntime if I could directly run gdb on your example.\n\nSpecifically, I'm interested in the call graph that leads to calling\nreprepare_packed_git().\n\n-Peff\n"},{"id":"304056","messageId":"20161012234753.tbqhuc7qdyklpfzv@sigill.intra.peff.net","threadId":"44292","inReplyTo":"20161012231807.syockv2emrsjf55r@sigill.intra.peff.net","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-12T23:47:53Z","receivedAt":"2016-10-12T23:55:24Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Oct 12, 2016 at 07:18:07PM -0400, Jeff King wrote:\n\n> Also, is it possible to make the repository in question available? I\n> might be able to reproduce based on your description, but it would save\n> time if I could directly run gdb on your example.\n\nI tried this by making a bunch of packs in linux.git (my standard \"this\nis pretty big\" repo), like so:\n\n for i in $(seq 1000); do\n git rev-list --objects HEAD~$((i+1))..HEAD~$i |\n git pack-objects --delta-base-offset .git/objects/pack/pack\n done\n\nand then doing a 25,000-object fetch from upstream (no significance to\nthe number; that's just how far behind upstream I happened to be).\n\nHowever, I didn't notice any regression. In fact, it was much _slower_\nthan v1.9.0, because that older version didn't have threaded index-pack.\n\nIf you can't share the repo directly, can you tell us more about your\nfetch? How many objects are in your repository? How many objects are\nfetched? How many refs are there on the remote side?\n\n-Peff\n"},{"id":"304064","messageId":"af801f22-0e24-525d-a862-f2114941719a@oracle.com","threadId":"44292","inReplyTo":"20161012230143.5kxcmtityaasra5j@sigill.intra.peff.net","subject":"Re: Huge performance bottleneck reading packs","fromName":"Vegard Nossum","fromEmail":"vegard.nossum@oracle.com","sentAt":"2016-10-13T07:20:07Z","receivedAt":"2016-10-13T07:21:54Z","isPatch":false,"sender":{"key":"vegard.nossum@oracle.com","avatar":"https://avatars.githubusercontent.com/u/24173?v=4"},"body":"On 10/13/2016 01:01 AM, Jeff King wrote:\n> On Thu, Oct 13, 2016 at 12:30:52AM +0200, Vegard Nossum wrote:\n>\n>> However, the commit found by 'git blame' above appears just fine to me,\n>> I haven't been able to spot a bug in it.\n>>\n>> A closer inspection reveals the problem to really be that this is an\n>> extremely hot path with more than -- holy cow -- 4,106,756,451\n>> iterations on the 'packed_git' list for a single 'git fetch' on my\n>> repository. I'm guessing the patch above just made the inner loop\n>> ever so slightly slower.\n>>\n>> My .git/objects/pack/ has ~2088 files (1042 idx files, 1042 pack files,\n>> and 4 tmp_pack_* files).\n>\n> Yeah. I agree that the commit you found makes the check a little more\n> expensive, but I think the root of the problem is calling\n> prepare_packed_git_one many times. This _should_ happen once for each\n> pack at program startup, and possibly again if we need to re-scan the\n> pack directory to account for racing with a simultaneous repack.\n>\n> The latter is generally triggered when we fail to look up an object we\n> expect to exist. So I'd suspect 45e8a74 (has_sha1_file: re-check pack\n> directory before giving up, 2013-08-30) is playing a part. We dealt with\n> that to some degree in 0eeb077 (index-pack: avoid excessive re-reading\n> of pack directory, 2015-06-09), but it would not surprise me if there is\n> another spot that needs similar treatment.\n>\n> Does the patch below help?\n\nYes, ~2m10s -> ~1m25s when I test a git fetch this morning (the other\nvariation in time may be due to different CPU usage by other programs,\nbut I ran with/without the patch multiple times and the difference is\nconsistent).\n\nThanks,\n\n\nVegard\n"},{"id":"304065","messageId":"fb66dc02-fb75-5aad-74e5-01b969cf9f9a@oracle.com","threadId":"44292","inReplyTo":"20161012234753.tbqhuc7qdyklpfzv@sigill.intra.peff.net","subject":"Re: Huge performance bottleneck reading packs","fromName":"Vegard Nossum","fromEmail":"vegard.nossum@oracle.com","sentAt":"2016-10-13T09:04:52Z","receivedAt":"2016-10-13T09:07:46Z","isPatch":false,"sender":{"key":"vegard.nossum@oracle.com","avatar":"https://avatars.githubusercontent.com/u/24173?v=4"},"body":"On 10/13/2016 01:47 AM, Jeff King wrote:\n> On Wed, Oct 12, 2016 at 07:18:07PM -0400, Jeff King wrote:\n>\n>> Also, is it possible to make the repository in question available? I\n>> might be able to reproduce based on your description, but it would save\n>> time if I could directly run gdb on your example.\n\nI won't be able to make the repository available, sorry.\n\n> I tried this by making a bunch of packs in linux.git (my standard \"this\n> is pretty big\" repo), like so:\n>\n> for i in $(seq 1000); do\n> git rev-list --objects HEAD~$((i+1))..HEAD~$i |\n> git pack-objects --delta-base-offset .git/objects/pack/pack\n> done\n>\n> and then doing a 25,000-object fetch from upstream (no significance to\n> the number; that's just how far behind upstream I happened to be).\n>\n> However, I didn't notice any regression. In fact, it was much _slower_\n> than v1.9.0, because that older version didn't have threaded index-pack.\n>\n> If you can't share the repo directly, can you tell us more about your\n> fetch? How many objects are in your repository? How many objects are\n> fetched? How many refs are there on the remote side?\n\nThe fetch doesn't actually get anything from the remote as everything is\nalready up to date (that makes the 2m40s times even more frustrating in\na way :-)). Here's count-objects:\n\n$ git count-objects -v\nwarning: garbage found: .git/objects/pack/tmp_pack_pAZcu4\nwarning: garbage found: .git/objects/pack/tmp_pack_KhzrrI\nwarning: garbage found: .git/objects/pack/tmp_pack_mycfro\nwarning: garbage found: .git/objects/pack/tmp_pack_2kxKOn\ncount: 51609\nsize: 288768\nin-pack: 23902336\npacks: 1044\nsize-pack: 16588157\nprune-packable: 48628\ngarbage: 4\nsize-garbage: 84792\n\nThere are some 20k refs on the remote, closer to 25k locally.\n\nI'll try to get a profile (without your patch) before doing a gc run.\n\n\nVegard\n"},{"id":"304066","messageId":"1d5dd36b-7a9e-ac00-352a-d71e0e277002@oracle.com","threadId":"44292","inReplyTo":"xmqqpon5190s.fsf@gitster.mtv.corp.google.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Vegard Nossum","fromEmail":"vegard.nossum@oracle.com","sentAt":"2016-10-13T07:17:34Z","receivedAt":"2016-10-13T09:57:42Z","isPatch":false,"sender":{"key":"vegard.nossum@oracle.com","avatar":"https://avatars.githubusercontent.com/u/24173?v=4"},"body":"On 10/13/2016 12:45 AM, Junio C Hamano wrote:\n > Vegard Nossum writes:\n >\n >> A closer inspection reveals the problem to really be that this is an\n >> extremely hot path with more than -- holy cow -- 4,106,756,451\n >> iterations on the 'packed_git' list for a single 'git fetch' on my\n >> repository. I'm guessing the patch above just made the inner loop\n >> ever so slightly slower.\n >\n > Very plausible, and this ...\n >\n >> My .git/objects/pack/ has ~2088 files (1042 idx files, 1042 pack files,\n >> and 4 tmp_pack_* files).\n >\n > ... may explain why nobody else has seen a difference.\n >\n > Is there a reason why your repository has that many pack files? Is\n > automatic GC not working for some reason?\n\nOops. I disabled gc a while ago; one reason I did that is that it takes\na long time to run and it has a tendency to kick in at the worst time. I\nguess I should really put it in cron then.\n\nI'm not sure if this is related, but I also had a problem with GitPython\nand large pack files in the past (\" ValueError: Couldn't obtain fanout\ntable or warning: packfile ./objects/pack/....pack cannot be accessed\")\nand I have pack.packSizeLimit set to 512m to fix that.\nAlthough the whole repo is 17G so I guess it shouldn't be necessary to\nhave that many pack files.\n\nWill try Jeff's patch, then a gc. Thanks!\n\n\nVegard\n"},{"id":"304076","messageId":"20161013145006.mouzqmz3fssrjad4@sigill.intra.peff.net","threadId":"44292","inReplyTo":"1d5dd36b-7a9e-ac00-352a-d71e0e277002@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-13T14:50:06Z","receivedAt":"2016-10-13T14:50:14Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 13, 2016 at 09:17:34AM +0200, Vegard Nossum wrote:\n\n> Oops. I disabled gc a while ago; one reason I did that is that it takes\n> a long time to run and it has a tendency to kick in at the worst time. I\n> guess I should really put it in cron then.\n> \n> I'm not sure if this is related, but I also had a problem with GitPython\n> and large pack files in the past (\" ValueError: Couldn't obtain fanout\n> table or warning: packfile ./objects/pack/....pack cannot be accessed\")\n\nSounds like they didn't correctly implement the extra index fanout that\nhappens for pack above 2G. The old Grit library had a similar bug.\n\n> and I have pack.packSizeLimit set to 512m to fix that.\n> Although the whole repo is 17G so I guess it shouldn't be necessary to\n> have that many pack files.\n\nUsing packSizeLimit does \"solve\" that problem, but it comes with its own\nset of issues. There is a very good chance that your repository would be\nmuch smaller than 17G as a single packfile, because Git does not allow\ndeltas across packs, and it does not optimize the placement of objects\nto keep delta-related objects in a single pack. So you'll quite often be\nstoring full copies of objects that could otherwise be stored as a tiny\ndelta.\n\nYou might want to compare the resulting size for a full repack with and\nwithout pack.packSizeLimit.\n\nBut I agree that is not the cause of your thousand packs. They are more\nlikely the accumulated cruft of a thousand fetches.\n\n-Peff\n"},{"id":"304085","messageId":"20161013152632.ynsabbv3yrthgidy@sigill.intra.peff.net","threadId":"44292","inReplyTo":"fb66dc02-fb75-5aad-74e5-01b969cf9f9a@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-13T15:26:32Z","receivedAt":"2016-10-13T16:27:08Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 13, 2016 at 09:20:07AM +0200, Vegard Nossum wrote:\n\n> > Does the patch below help?\n> \n> Yes, ~2m10s -> ~1m25s when I test a git fetch this morning (the other\n> variation in time may be due to different CPU usage by other programs,\n> but I ran with/without the patch multiple times and the difference is\n> consistent).\n> [...]\n> There are some 20k refs on the remote, closer to 25k locally.\n\nOK, that makes some sense. For whatever reason, your remote has a bunch\nof tags that point to objects you do not already have. That could\nhappen, I think, if the remote added a lot of tags since you cloned\n(because clone will grab all of the tags), but those tags do not point\nto history that you are otherwise fetching (since fetch by default will\n\"auto-follow\" such tags).\n\nIt might be interesting to see the results of:\n\n # all the objects we have\n git cat-file --batch-all-objects --batch-check='%(objectname)' >us\n\n # all the objects the remote is advertising\n git ls-remote origin | cut -f1 | sort -u >them\n\n # what they are advertising that we don't have\n comm -13 us them | wc -l\n\nMy guess is that the number is relatively high. And that would explain\nwhy nobody else has really complained much; such a pattern is probably\nuncommon.\n\n> The fetch doesn't actually get anything from the remote as everything is\n> already up to date (that makes the 2m40s times even more frustrating in\n> a way :-)). Here's count-objects:\n\nIf the fetch is largely a noop, then that makes me wonder why we are\nspending even a minute in the \"good\" case. I wonder if there is some\nother spot that is wasting CPU on some inefficient data structure\nrelated to the number of refs you have. If you can do any profiling that\npoints to a hot spot, that would be interesting to see (and also whether\na gc improves things).\n\nI see in find_non_local_tags() that we build up a sorted string_list via\nrepeated calls to string_list_insert(), which will keep the thing sorted\nat each stage. That's not as efficient as just sorting at the end, but I\nthink it's probably OK in practice because we actually feed it via\nfor_each_ref(), whose output is sorted, and so we'd always just be\nappending to the end.\n\n-Peff\n"},{"id":"304086","messageId":"20161013165344.jv7hyj74q33yb4ip@sigill.intra.peff.net","threadId":"44292","inReplyTo":"20161013152632.ynsabbv3yrthgidy@sigill.intra.peff.net","subject":"[PATCH] fetch: use \"quick\" has_sha1_file for tag following","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-13T16:53:44Z","receivedAt":"2016-10-13T16:53:51Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 13, 2016 at 11:26:32AM -0400, Jeff King wrote:\n\n> On Thu, Oct 13, 2016 at 09:20:07AM +0200, Vegard Nossum wrote:\n> \n> > > Does the patch below help?\n> > \n> > Yes, ~2m10s -> ~1m25s when I test a git fetch this morning (the other\n> > variation in time may be due to different CPU usage by other programs,\n> > but I ran with/without the patch multiple times and the difference is\n> > consistent).\n> > [...]\n> > There are some 20k refs on the remote, closer to 25k locally.\n> \n> OK, that makes some sense. For whatever reason, your remote has a bunch\n> of tags that point to objects you do not already have. That could\n> happen, I think, if the remote added a lot of tags since you cloned\n> (because clone will grab all of the tags), but those tags do not point\n> to history that you are otherwise fetching (since fetch by default will\n> \"auto-follow\" such tags).\n\nArmed with this information, I was able to reproduce the issue locally.\nHowever, once my patch is applied, it's now quite fast. So I still don't\nknow where your other 1m25s is going.\n\nSo here's that same patch wrapped up with a commit message. Note that I\nconverted one more call site to the \"quick\" form; it would trigger when\nthe candidate tags are real tag objects, not just pointers to commits.\nThat might improve your runtime more, depending on what is actually in\nyour repository.\n\n-- >8 --\nSubject: [PATCH] fetch: use \"quick\" has_sha1_file for tag following\n\nWhen we auto-follow tags in a fetch, we look at all of the\ntags advertised by the remote and fetch ones where we don't\nalready have the tag, but we do have the object it peels to.\nThis involves a lot of calls to has_sha1_file(), some of\nwhich we can reasonably expect to fail. Since 45e8a74\n(has_sha1_file: re-check pack directory before giving up,\n2013-08-30), this may cause many calls to\nreprepare_packed_git(), which is potentially expensive.\n\nThis has gone unnoticed for several years because it\nrequires a fairly unique setup to matter:\n\n 1. You need to have a lot of packs on the client side to\n make reprepare_packed_git() expensive (the most\n expensive part is finding duplicates in an unsorted\n list, which is currently quadratic).\n\n 2. You need a large number of tag refs on the server side\n that are candidates for auto-following (i.e., that the\n client doesn't have). Each one triggers a re-read of\n the pack directory.\n\n 3. Under normal circumstances, the client would\n auto-follow those tags and after one large fetch, (2)\n would no longer be true. But if those tags point to\n history which is disconnected from what the client\n otherwise fetches, then it will never auto-follow, and\n those candidates will impact it on every fetch.\n\nSo when all three are true, each fetch pays an extra\nO(nr_tags * nr_packs^2) cost, mostly in string comparisons\non the pack names. This was exacerbated by 47bf4b0\n(prepare_packed_git_one: refactor duplicate-pack check,\n2014-06-30) which uses a slightly more expensive string\ncheck, under the assumption that the duplicate check doesn't\nhappen very often (and it shouldn't; the real problem here\nis how often we are calling reprepare_packed_git()).\n\nThis patch teaches fetch to use HAS_SHA1_QUICK to sacrifice\naccuracy for speed, in cases where we might be racy with a\nsimultaneous repack. This is similar to the fix in 0eeb077\n(index-pack: avoid excessive re-reading of pack directory,\n2015-06-09). As with that case, it's OK for has_sha1_file()\noccasionally say \"no I don't have it\" when we do, because\nthe worst case is not a corruption, but simply that we may\nfail to auto-follow a tag that points to it.\n\nHere are results from the included perf script, which sets\nup a situation similar to the one described above:\n\nTest HEAD^ HEAD\n----------------------------------------------------------\n5550.4: fetch 11.21(10.42+0.78) 0.08(0.04+0.02) -99.3%\n\nReported-by: Vegard Nossum \nSigned-off-by: Jeff King \n---\n builtin/fetch.c | 11 ++++--\n cache.h | 1 +\n sha1_file.c | 5 +++\n t/perf/p5550-fetch-tags.sh | 99 ++++++++++++++++++++++++++++++++++++++++++++++\n 4 files changed, 112 insertions(+), 4 deletions(-)\n create mode 100755 t/perf/p5550-fetch-tags.sh\n\ndiff --git a/builtin/fetch.c b/builtin/fetch.c\nindex d5329f9..74c0546 100644\n--- a/builtin/fetch.c\n+++ b/builtin/fetch.c\n@@ -241,9 +241,10 @@ static void find_non_local_tags(struct transport *transport,\n \t\t * as one to ignore by setting util to NULL.\n \t\t */\n \t\tif (ends_with(ref->name, \"^{}\")) {\n-\t\t\tif (item && !has_object_file(&ref->old_oid) &&\n+\t\t\tif (item &&\n+\t\t\t !has_object_file_with_flags(&ref->old_oid, HAS_SHA1_QUICK) &&\n \t\t\t !will_fetch(head, ref->old_oid.hash) &&\n-\t\t\t !has_sha1_file(item->util) &&\n+\t\t\t !has_sha1_file_with_flags(item->util, HAS_SHA1_QUICK) &&\n \t\t\t !will_fetch(head, item->util))\n \t\t\t\titem->util = NULL;\n \t\t\titem = NULL;\n@@ -256,7 +257,8 @@ static void find_non_local_tags(struct transport *transport,\n \t\t * to check if it is a lightweight tag that we want to\n \t\t * fetch.\n \t\t */\n-\t\tif (item && !has_sha1_file(item->util) &&\n+\t\tif (item &&\n+\t\t !has_sha1_file_with_flags(item->util, HAS_SHA1_QUICK) &&\n \t\t !will_fetch(head, item->util))\n \t\t\titem->util = NULL;\n \n@@ -276,7 +278,8 @@ static void find_non_local_tags(struct transport *transport,\n \t * We may have a final lightweight tag that needs to be\n \t * checked to see if it needs fetching.\n \t */\n-\tif (item && !has_sha1_file(item->util) &&\n+\tif (item &&\n+\t !has_sha1_file_with_flags(item->util, HAS_SHA1_QUICK) &&\n \t !will_fetch(head, item->util))\n \t\titem->util = NULL;\n \ndiff --git a/cache.h b/cache.h\nindex 2cfb1ca..ec791a6 100644\n--- a/cache.h\n+++ b/cache.h\n@@ -1154,6 +1154,7 @@ static inline int has_sha1_file(const unsigned char *sha1)\n \n /* Same as the above, except for struct object_id. */\n extern int has_object_file(const struct object_id *oid);\n+extern int has_object_file_with_flags(const struct object_id *oid, int flags);\n \n /*\n * Return true iff an alternate object database has a loose object\ndiff --git a/sha1_file.c b/sha1_file.c\nindex 309e87d..c652cb6 100644\n--- a/sha1_file.c\n+++ b/sha1_file.c\n@@ -3309,6 +3309,11 @@ int has_object_file(const struct object_id *oid)\n \treturn has_sha1_file(oid->hash);\n }\n \n+int has_object_file_with_flags(const struct object_id *oid, int flags)\n+{\n+\treturn has_sha1_file_with_flags(oid->hash, flags);\n+}\n+\n static void check_tree(const void *buf, size_t size)\n {\n \tstruct tree_desc desc;\ndiff --git a/t/perf/p5550-fetch-tags.sh b/t/perf/p5550-fetch-tags.sh\nnew file mode 100755\nindex 0000000..a5dc39f\n--- /dev/null\n+++ b/t/perf/p5550-fetch-tags.sh\n@@ -0,0 +1,99 @@\n+#!/bin/sh\n+\n+test_description='performance of tag-following with many tags\n+\n+This tests a fairly pathological case, so rather than rely on a real-world\n+case, we will construct our own repository. The situation is roughly as\n+follows.\n+\n+The parent repository has a large number of tags which are disconnected from\n+the rest of history. That makes them candidates for tag-following, but we never\n+actually grab them (and thus they will impact each subsequent fetch).\n+\n+The child repository is a clone of parent, without the tags, and is at least\n+one commit behind the parent (meaning that we will fetch one object and then\n+examine the tags to see if they need followed). Furthermore, it has a large\n+number of packs.\n+\n+The exact values of \"large\" here are somewhat arbitrary; I picked values that\n+start to show a noticeable performance problem on my machine, but without\n+taking too long to set up and run the tests.\n+'\n+. ./perf-lib.sh\n+\n+# make a long nonsense history on branch $1, consisting of $2 commits, each\n+# with a unique file pointing to the blob at $2.\n+create_history () {\n+\tperl -le '\n+\t\tmy ($branch, $n, $blob) = @ARGV;\n+\t\tfor (1..$n) {\n+\t\t\tprint \"commit refs/heads/$branch\";\n+\t\t\tprint \"committer nobody now\";\n+\t\t\tprint \"data 4\";\n+\t\t\tprint \"foo\";\n+\t\t\tprint \"M 100644 $blob $_\";\n+\t\t}\n+\t' \"$@\" |\n+\tgit fast-import --date-format=now\n+}\n+\n+# make a series of tags, one per commit in the revision range given by $@\n+create_tags () {\n+\tgit rev-list \"$@\" |\n+\tperl -lne 'print \"create refs/tags/$. $_\"' |\n+\tgit update-ref --stdin\n+}\n+\n+# create $1 nonsense packs, each with a single blob\n+create_packs () {\n+\tperl -le '\n+\t\tmy ($n) = @ARGV;\n+\t\tfor (1..$n) {\n+\t\t\tprint \"blob\";\n+\t\t\tprint \"data < -- >8 --\n> Subject: [PATCH] fetch: use \"quick\" has_sha1_file for tag following\n\nA few comments on my own patch...\n\n> This patch teaches fetch to use HAS_SHA1_QUICK to sacrifice\n> accuracy for speed, in cases where we might be racy with a\n> simultaneous repack. This is similar to the fix in 0eeb077\n> (index-pack: avoid excessive re-reading of pack directory,\n> 2015-06-09). As with that case, it's OK for has_sha1_file()\n> occasionally say \"no I don't have it\" when we do, because\n> the worst case is not a corruption, but simply that we may\n> fail to auto-follow a tag that points to it.\n\nFailing in this direction doesn't make me feel great. I had hoped it\nwould fail the _other_ way, and request an object that we might already\nhave.\n\nThere are two alternatives that might be worth pursuing:\n\n 1. The thing that makes this really painful is the quadratic\n duplicate-search in prepare_packed_git_one(). We could speed that\n up pretty easily by keeping a hash of the packs indexed by their\n names, and looking up in that.\n\n That drops the quadratic factor, but it's still going to be\n O(nr_tags * nr_packs), as we have to at the very least readdir()\n all of objects/pack to see that nothing new showed up.\n\n I wonder if we could trust the timestamp on the objects/pack\n directory to avoid re-reading it at all. That turns it into a\n single stat() call.\n\n 2. We could stop bothering to reprepare_packed_git() only after the\n nth time it is called. This basically turns on the \"sacrifice\n accuracy for speed\" behavior automatically, but it means that most\n cases would never do so, because it wouldn't be creating a\n performance issue in the first place.\n\n It feels weird and flaky that git might behave differently based on\n the number of unfetched tags the remote happens to have, though.\n\n> Here are results from the included perf script, which sets\n> up a situation similar to the one described above:\n> \n> Test HEAD^ HEAD\n> ----------------------------------------------------------\n> 5550.4: fetch 11.21(10.42+0.78) 0.08(0.04+0.02) -99.3%\n\nThe situation in this perf script is obviously designed to show off this\none specific optimization. It feels a bit overly specific, and I doubt\nanybody will be all that interested in running it again once the fix is\nin. OTOH, I did want to document my reproduction steps, and this seemed\nlike the only reasonable place to do so. And as the perf suite is\nalready pretty expensive, perhaps nobody minds adding to it too much.\n\n-Peff\n"},{"id":"304088","messageId":"d727ee5d-5f0f-e6df-3f83-35fe74641ace@oracle.com","threadId":"44292","inReplyTo":"20161013152632.ynsabbv3yrthgidy@sigill.intra.peff.net","subject":"Re: Huge performance bottleneck reading packs","fromName":"Vegard Nossum","fromEmail":"vegard.nossum@oracle.com","sentAt":"2016-10-13T18:18:11Z","receivedAt":"2016-10-13T18:18:30Z","isPatch":false,"sender":{"key":"vegard.nossum@oracle.com","avatar":"https://avatars.githubusercontent.com/u/24173?v=4"},"body":"On 10/13/2016 05:26 PM, Jeff King wrote:\n> On Thu, Oct 13, 2016 at 09:20:07AM +0200, Vegard Nossum wrote:\n>\n>>> Does the patch below help?\n>>\n>> Yes, ~2m10s -> ~1m25s when I test a git fetch this morning (the other\n>> variation in time may be due to different CPU usage by other programs,\n>> but I ran with/without the patch multiple times and the difference is\n>> consistent).\n>> [...]\n>> There are some 20k refs on the remote, closer to 25k locally.\n>\n> OK, that makes some sense. For whatever reason, your remote has a bunch\n> of tags that point to objects you do not already have. That could\n> happen, I think, if the remote added a lot of tags since you cloned\n> (because clone will grab all of the tags), but those tags do not point\n> to history that you are otherwise fetching (since fetch by default will\n> \"auto-follow\" such tags).\n>\n> It might be interesting to see the results of:\n>\n> # all the objects we have\n> git cat-file --batch-all-objects --batch-check='%(objectname)' >us\n>\n> # all the objects the remote is advertising\n> git ls-remote origin | cut -f1 | sort -u >them\n>\n> # what they are advertising that we don't have\n> comm -13 us them | wc -l\n>\n> My guess is that the number is relatively high. And that would explain\n> why nobody else has really complained much; such a pattern is probably\n> uncommon.\n\nI get ~3,700 objects \"they are advertising that we don't have\".\n\nThey are all indeed tags which I don't have (nor want) locally.\n\n>> The fetch doesn't actually get anything from the remote as everything is\n>> already up to date (that makes the 2m40s times even more frustrating in\n>> a way :-)). Here's count-objects:\n>\n> If the fetch is largely a noop, then that makes me wonder why we are\n> spending even a minute in the \"good\" case. I wonder if there is some\n\nIt was user time I reported and this is over network, so some of it\nmight be IO wait on the network? With the (first) patch:\n\n$ time git fetch\n\nreal 1m9.248s\nuser 0m40.808s\nsys 0m2.996s\n\nAlso see the profile data below.\n\n> other spot that is wasting CPU on some inefficient data structure\n> related to the number of refs you have. If you can do any profiling that\n> points to a hot spot, that would be interesting to see (and also whether\n> a gc improves things).\n>\n> I see in find_non_local_tags() that we build up a sorted string_list via\n> repeated calls to string_list_insert(), which will keep the thing sorted\n> at each stage. That's not as efficient as just sorting at the end, but I\n> think it's probably OK in practice because we actually feed it via\n> for_each_ref(), whose output is sorted, and so we'd always just be\n> appending to the end.\n\nSo without your patch I get these numbers:\n\n % cumulative self self total\n time seconds seconds calls s/call s/call name\n 37.34 29.83 29.83 1948265116 0.00 0.00 strip_suffix_mem\n 27.56 51.85 22.02 11358 0.00 0.01 \nprepare_packed_git_one\n 14.24 63.23 11.38 1924457702 0.00 0.00 strip_suffix\n 4.88 67.13 3.90 26045319 0.00 0.00 find_pack_entry_one\n 4.17 70.46 3.33 84828149 0.00 0.00 hashcmp\n 3.28 73.08 2.62 79760199 0.00 0.00 hashcmp\n 2.44 75.03 1.95 const_error\n\nthe call graph data shows all the reprepare_packed_git() calls to come\nfrom a chain like this:\n\ndo_for_each_ref\ndo_for_each_ref_iterator\nref_iterator_advance\nfiles_ref_iterator_advance\nref_resolves_to_object\nhas_sha1_file\nhas_sha1_file_with_flags\nreprepare_packed_git\n\nthe do_for_each_ref() calls come from prepare_replace_object(),\ndo_fetch(), find_common(), everything_local(),\ncheck_for_new_submodule_commits(), and find_non_local_tags().\n\nWith your (first) patch I get this instead:\n\n % cumulative self self total\n time seconds seconds calls ms/call ms/call name\n 29.41 0.25 0.25 4490399 0.00 0.00 hashcmp\n 16.47 0.39 0.14 843447 0.00 0.00 find_pack_entry_one\n 10.59 0.48 0.09 60490 0.00 0.00 \nunpack_object_header_buffer\n 4.71 0.52 0.04 167441 0.00 0.00 lookup_object\n 3.53 0.55 0.03 843447 0.00 0.00 fill_pack_entry\n 3.53 0.58 0.03 213169 0.00 0.00 \ncheck_refname_component\n 2.35 0.60 0.02 550723 0.00 0.00 strip_suffix_mem\n 2.35 0.62 0.02 214607 0.00 0.00 insert_obj_hash\n 2.35 0.64 0.02 158866 0.00 0.00 hashcmp\n 2.35 0.66 0.02 153936 0.00 0.00 \nnth_packed_object_offset\n\nDo you have all the profile data you were interested in before I try a\n'git gc'?\n\nI really appreciate the quick response and the work you put into fixing\nthis, even when it's my fault for disabling gc, thanks!\n\n\nVegard\n"},{"id":"304092","messageId":"20161013200644.lnustevmpvufbg5y@sigill.intra.peff.net","threadId":"44292","inReplyTo":"20161013170443.43slna3zvcvrse5r@sigill.intra.peff.net","subject":"Re: [PATCH] fetch: use \"quick\" has_sha1_file for tag following","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-13T20:06:44Z","receivedAt":"2016-10-13T20:13:53Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 13, 2016 at 01:04:43PM -0400, Jeff King wrote:\n\n> > This patch teaches fetch to use HAS_SHA1_QUICK to sacrifice\n> > accuracy for speed, in cases where we might be racy with a\n> > simultaneous repack. This is similar to the fix in 0eeb077\n> > (index-pack: avoid excessive re-reading of pack directory,\n> > 2015-06-09). As with that case, it's OK for has_sha1_file()\n> > occasionally say \"no I don't have it\" when we do, because\n> > the worst case is not a corruption, but simply that we may\n> > fail to auto-follow a tag that points to it.\n> \n> Failing in this direction doesn't make me feel great. I had hoped it\n> would fail the _other_ way, and request an object that we might already\n> have.\n> \n> There are two alternatives that might be worth pursuing:\n> \n> 1. The thing that makes this really painful is the quadratic\n> duplicate-search in prepare_packed_git_one(). We could speed that\n> up pretty easily by keeping a hash of the packs indexed by their\n> names, and looking up in that.\n> \n> That drops the quadratic factor, but it's still going to be\n> O(nr_tags * nr_packs), as we have to at the very least readdir()\n> all of objects/pack to see that nothing new showed up.\n\nThat hash patch would look something like what is below.\n\nHere are numbers for the perf script (\"quick\" is the one that skips\nreprepare entirely, \"hash\" is this hash table patch, and \"quick+hash\" is\nthe combination of the two):\n\norigin quick hash quick+hash \n--------------------------------------------------------------------------------------------\n11.09(10.38+0.70) 0.08(0.06+0.01) -99.3% 1.41(0.65+0.75) -87.3% 0.07(0.05+0.01) -99.4%\n\nSo yes, it does improve this case, but not nearly as much as the \"quick\"\napproach. Putting it on top of the \"quick\" approach is barely noticeable\n(it is speeding up the initial prepare_packed_git() call, but it's just\nnot expensive enough in the first place to be worth it).\n\nThe \"hash\" patch does fix a potentially quadratic behavior, though, so I\nguess in theory it is worth it. But I had to go up to quite a large\nnumber of packs to make it worthwhile. Here it is at 7500 packs, running\n\"git cat-file -e $some_object_that_exists\":\n\n [origin]\n real 0m0.417s\n user 0m0.376s\n sys 0m0.040s\n\n [hash]\n real 0m0.054s\n user 0m0.008s\n sys 0m0.044s\n\nSo it's certainly better. But 7500 packs is just silly, and squeezing\nout ~400ms there is hardly worth it. If you repack this same case into a\nsingle pack, the command drops to 5ms. So yes, there's close to an order\nof magnitude speedup here, but you get that _and_ another order of\nmagnitude just by repacking.\n\nSo I think it's only worth pursuing if we wanted to scrap my original\npatch, and continue to aggressively reprepare_packed_git(). I'd worry\nthat it's still expensive on some systems, even with the hash, because\nthe opendir/readdir might cost a lot (OTOH, we'll by definition have\njust done a stat() on the loose version of the object, so there's a\nlimit to how fast we can make it).\n\nI dunno.\n\n---\n cache.h | 2 ++\n sha1_file.c | 44 +++++++++++++++++++++++++++++++++++---------\n 2 files changed, 37 insertions(+), 9 deletions(-)\n\ndiff --git a/cache.h b/cache.h\nindex ec791a6..0d8b4e8 100644\n--- a/cache.h\n+++ b/cache.h\n@@ -1411,6 +1411,7 @@ struct pack_window {\n };\n \n extern struct packed_git {\n+\tstruct hashmap_entry name_entry;\n \tstruct packed_git *next;\n \tstruct pack_window *windows;\n \toff_t pack_size;\n@@ -1428,6 +1429,7 @@ extern struct packed_git {\n \t\t do_not_close:1;\n \tunsigned char sha1[20];\n \tstruct revindex_entry *revindex;\n+\tsize_t basename_len;\n \t/* something like \".git/objects/pack/xxxxx.pack\" */\n \tchar pack_name[FLEX_ARRAY]; /* more */\n } *packed_git;\ndiff --git a/sha1_file.c b/sha1_file.c\nindex c652cb6..eb6a5f3 100644\n--- a/sha1_file.c\n+++ b/sha1_file.c\n@@ -602,6 +602,8 @@ struct packed_git *packed_git;\n static struct mru packed_git_mru_storage;\n struct mru *packed_git_mru = &packed_git_mru_storage;\n \n+static struct hashmap pack_name_index;\n+\n void pack_report(void)\n {\n \tfprintf(stderr,\n@@ -1260,6 +1262,30 @@ struct packed_git *parse_pack_index(unsigned char *sha1, const char *idx_path)\n \treturn p;\n }\n \n+static int pack_name_hashcmp(const void *va, const void *vb, const void *name)\n+{\n+\tconst struct packed_git *a = va, *b = vb;\n+\n+\tif (a->basename_len != b->basename_len)\n+\t\treturn -1;\n+\telse if (name)\n+\t\treturn memcmp(a->pack_name, name, a->basename_len);\n+\telse\n+\t\treturn memcmp(a->pack_name, b->pack_name, a->basename_len);\n+}\n+\n+static int pack_loaded(const char *name, size_t len)\n+{\n+\tstruct packed_git key;\n+\n+\tif (!pack_name_index.tablesize)\n+\t\treturn 0;\n+\n+\thashmap_entry_init(&key, memhash(name, len));\n+\tkey.basename_len = len;\n+\treturn !!hashmap_get(&pack_name_index, &key, name);\n+}\n+\n void install_packed_git(struct packed_git *pack)\n {\n \tif (pack->pack_fd != -1)\n@@ -1267,6 +1293,12 @@ void install_packed_git(struct packed_git *pack)\n \n \tpack->next = packed_git;\n \tpacked_git = pack;\n+\n+\tif (!pack_name_index.tablesize)\n+\t\thashmap_init(&pack_name_index, pack_name_hashcmp, 0);\n+\tstrip_suffix(pack->pack_name, \".pack\", &pack->basename_len);\n+\thashmap_entry_init(pack, memhash(pack->pack_name, pack->basename_len));\n+\thashmap_add(&pack_name_index, pack);\n }\n \n void (*report_garbage)(unsigned seen_bits, const char *path);\n@@ -1347,15 +1379,9 @@ static void prepare_packed_git_one(char *objdir, int local)\n \n \t\tbase_len = path.len;\n \t\tif (strip_suffix_mem(path.buf, &base_len, \".idx\")) {\n-\t\t\t/* Don't reopen a pack we already have. */\n-\t\t\tfor (p = packed_git; p; p = p->next) {\n-\t\t\t\tsize_t len;\n-\t\t\t\tif (strip_suffix(p->pack_name, \".pack\", &len) &&\n-\t\t\t\t len == base_len &&\n-\t\t\t\t !memcmp(p->pack_name, path.buf, len))\n-\t\t\t\t\tbreak;\n-\t\t\t}\n-\t\t\tif (p == NULL &&\n+\t\t\tif (\n+\t\t\t /* Don't reopen a pack we already have. */\n+\t\t\t !pack_loaded(path.buf, base_len) &&\n \t\t\t /*\n \t\t\t * See if it really is a valid .idx file with\n \t\t\t * corresponding .pack file that we can map.\n-- \n2.10.1.589.gca16299\n\n"},{"id":"304094","messageId":"20161013204351.rezqssvw63343l4g@sigill.intra.peff.net","threadId":"44292","inReplyTo":"d727ee5d-5f0f-e6df-3f83-35fe74641ace@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-13T20:43:51Z","receivedAt":"2016-10-13T20:45:21Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 13, 2016 at 08:18:11PM +0200, Vegard Nossum wrote:\n\n> > My guess is that the number is relatively high. And that would explain\n> > why nobody else has really complained much; such a pattern is probably\n> > uncommon.\n> \n> I get ~3,700 objects \"they are advertising that we don't have\".\n> \n> They are all indeed tags which I don't have (nor want) locally.\n\nThanks. That's about what I expected.\n\n> So without your patch I get these numbers:\n> \n> % cumulative self self total\n> time seconds seconds calls s/call s/call name\n> 37.34 29.83 29.83 1948265116 0.00 0.00 strip_suffix_mem\n> 27.56 51.85 22.02 11358 0.00 0.01 prepare_packed_git_one\n> 14.24 63.23 11.38 1924457702 0.00 0.00 strip_suffix\n> 4.88 67.13 3.90 26045319 0.00 0.00 find_pack_entry_one\n> 4.17 70.46 3.33 84828149 0.00 0.00 hashcmp\n> 3.28 73.08 2.62 79760199 0.00 0.00 hashcmp\n> 2.44 75.03 1.95 const_error\n> \n> the call graph data shows all the reprepare_packed_git() calls to come\n> from a chain like this:\n> \n> do_for_each_ref\n> do_for_each_ref_iterator\n> ref_iterator_advance\n> files_ref_iterator_advance\n> ref_resolves_to_object\n> has_sha1_file\n> has_sha1_file_with_flags\n> reprepare_packed_git\n\nHrm. It seems weird that we'd hit reprepare_packed_git() via\ndo_for_each_ref(), because that's looking at _your_ refs. So any time\nthat code path hits reprepare_packed_git(), it should be complaining\nabout repository corruption to stderr.\n\nAnd that also wouldn't make sense that my patch would improve it. Are\nyou sure you've read the perf output correctly (I'll admit that I am\noften confused by the way it reports call graphs)?\n\n> With your (first) patch I get this instead:\n> \n> % cumulative self self total\n> time seconds seconds calls ms/call ms/call name\n> 29.41 0.25 0.25 4490399 0.00 0.00 hashcmp\n> 16.47 0.39 0.14 843447 0.00 0.00 find_pack_entry_one\n\nThese functions appearing at the top are probably a sign that you have\ntoo many packs (these are just object lookup, which has to linearly try\neach pack).\n\nSo I'd expect things to improve after a git-gc (and especially if you\nturn off the packSizeLimit).\n\n> Do you have all the profile data you were interested in before I try a\n> 'git gc'?\n\nYes, I think so. At least I'm satisfied that there's not another\nHAS_SHA1_QUICK case that I'm missing.\n\n> I really appreciate the quick response and the work you put into fixing\n> this, even when it's my fault for disabling gc, thanks!\n\nNo problem. I do think you'll benefit a lot from packing everything into\na single pack, but it's also clear that Git was doing more work than it\nneeded to be. This was a known issue when we added the racy-check to\nhas_sha1_file(), and knew that we might have to field reports like this\none.\n\n-Peff\n"},{"id":"304102","messageId":"0e4173b6-8fbb-4223-b061-524c7ebfd4d7@oracle.com","threadId":"44292","inReplyTo":"20161013204351.rezqssvw63343l4g@sigill.intra.peff.net","subject":"Re: Huge performance bottleneck reading packs","fromName":"Vegard Nossum","fromEmail":"vegard.nossum@oracle.com","sentAt":"2016-10-14T06:55:29Z","receivedAt":"2016-10-14T06:56:10Z","isPatch":false,"sender":{"key":"vegard.nossum@oracle.com","avatar":"https://avatars.githubusercontent.com/u/24173?v=4"},"body":"On 10/13/2016 10:43 PM, Jeff King wrote:\n> No problem. I do think you'll benefit a lot from packing everything into\n> a single pack, but it's also clear that Git was doing more work than it\n> needed to be. This was a known issue when we added the racy-check to\n> has_sha1_file(), and knew that we might have to field reports like this\n> one.\n\nAfter 'git gc' (with the .5G limit) I have 23 packs and with your patch\nI now get:\n\n$ time git fetch\n\nreal 0m26.520s\nuser 0m3.580s\nsys 0m0.636s\n\nThanks!\n\n\nvegard\n"},{"id":"304103","messageId":"3933cae1-1c2d-e32e-3fea-dc80a2f77ddb@gmail.com","threadId":"44292","inReplyTo":"fb66dc02-fb75-5aad-74e5-01b969cf9f9a@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jakub Narębski","fromEmail":"jnareb@gmail.com","sentAt":"2016-10-14T09:35:18Z","receivedAt":"2016-10-14T09:35:36Z","isPatch":false,"sender":{"key":"jnareb@gmail.com","avatar":"https://avatars.githubusercontent.com/u/2706?v=4"},"body":"W dniu 13.10.2016 o 11:04, Vegard Nossum pisze:\n> On 10/13/2016 01:47 AM, Jeff King wrote:\n>> On Wed, Oct 12, 2016 at 07:18:07PM -0400, Jeff King wrote:\n>>\n>>> Also, is it possible to make the repository in question available? I\n>>> might be able to reproduce based on your description, but it would save\n>>> time if I could directly run gdb on your example.\n> \n> I won't be able to make the repository available, sorry.\n\nWe have 'git fast-export --anonymize ...', but it would obviously\nnot preserve the pack structure (though it can help in other cases\nwhen one cannot make repository available).\n\n-- \nJakub Narębski\n\n"},{"id":"304184","messageId":"xmqqfunyzv6f.fsf@gitster.mtv.corp.google.com","threadId":"44292","inReplyTo":"20161013200644.lnustevmpvufbg5y@sigill.intra.peff.net","subject":"Re: [PATCH] fetch: use \"quick\" has_sha1_file for tag following","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2016-10-14T17:39:52Z","receivedAt":"2016-10-14T17:40:35Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> So it's certainly better. But 7500 packs is just silly, and squeezing\n> out ~400ms there is hardly worth it. If you repack this same case into a\n> single pack, the command drops to 5ms. So yes, there's close to an order\n> of magnitude speedup here, but you get that _and_ another order of\n> magnitude just by repacking.\n\n\"7500 is silly\" equally applies to the \"quick\" (and sloppy, if I am\nreading your \"Failing in this direction doesn't make me feel great.\"\ncorrectly) approach, I think, which argues for not taking either\nchange X-<.\n\nI agree that the fallout from the inaccuracy of \"quick\" approach is\nprobably acceptable and the next \"fetch\" will correct it anyway, so\nlet's do the \"quick but inaccurate\" for now and perhaps cook it in\n'next' for a bit longer than other topics?\n"},{"id":"304200","messageId":"20161014190051.oxrfreb56nogkdv7@sigill.intra.peff.net","threadId":"44292","inReplyTo":"0e4173b6-8fbb-4223-b061-524c7ebfd4d7@oracle.com","subject":"Re: Huge performance bottleneck reading packs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-14T19:00:51Z","receivedAt":"2016-10-16T00:33:57Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 14, 2016 at 08:55:29AM +0200, Vegard Nossum wrote:\n\n> On 10/13/2016 10:43 PM, Jeff King wrote:\n> > No problem. I do think you'll benefit a lot from packing everything into\n> > a single pack, but it's also clear that Git was doing more work than it\n> > needed to be. This was a known issue when we added the racy-check to\n> > has_sha1_file(), and knew that we might have to field reports like this\n> > one.\n> \n> After 'git gc' (with the .5G limit) I have 23 packs and with your patch\n> I now get:\n> \n> $ time git fetch\n> \n> real 0m26.520s\n> user 0m3.580s\n> sys 0m0.636s\n\nCool. That's about what I'd expect based on the size numbers you gave\nearlier. The other 23 seconds are likely being spent on passing the ref\nadvertisement over the network.\n\n-Peff\n"},{"id":"304220","messageId":"20161014185953.k4b5xwihlgvxurjc@sigill.intra.peff.net","threadId":"44292","inReplyTo":"xmqqfunyzv6f.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH] fetch: use \"quick\" has_sha1_file for tag following","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-14T18:59:53Z","receivedAt":"2016-10-16T00:34:34Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 14, 2016 at 10:39:52AM -0700, Junio C Hamano wrote:\n\n> Jeff King writes:\n> \n> > So it's certainly better. But 7500 packs is just silly, and squeezing\n> > out ~400ms there is hardly worth it. If you repack this same case into a\n> > single pack, the command drops to 5ms. So yes, there's close to an order\n> > of magnitude speedup here, but you get that _and_ another order of\n> > magnitude just by repacking.\n> \n> \"7500 is silly\" equally applies to the \"quick\" (and sloppy, if I am\n> reading your \"Failing in this direction doesn't make me feel great.\"\n> correctly) approach, I think, which argues for not taking either\n> change X-<.\n\nI wouldn't quite agree that they're the same. 7500 packs is silly\nbecause a bunch of _other_ things are going to get equally or more slow\nbefore the prepare_packed_git() slowdown is noticeable. And it's in your\npower to clean up, and we should encourage users to do so.\n\nWhereas having a bunch of unfetched tags is a state that may linger\nindefinitely, and be outside the user's control.\n\nI _am_ open to the argument that calling reprepare_packed_git() over and\nover doesn't really matter much if you have a sane number of packs. If\nyou tweak my perf test like so:\n\ndiff --git a/t/perf/p5550-fetch-tags.sh b/t/perf/p5550-fetch-tags.sh\nindex a5dc39f..7e7ae24 100755\n--- a/t/perf/p5550-fetch-tags.sh\n+++ b/t/perf/p5550-fetch-tags.sh\n@@ -86,7 +86,7 @@ test_expect_success 'create child packs' '\n \t\tcd child &&\n \t\tgit config gc.auto 0 &&\n \t\tgit config gc.autopacklimit 0 &&\n-\t\tcreate_packs 500\n+\t\tcreate_packs 10\n \t)\n '\n \n\nyou get:\n\nTest origin quick \n--------------------------------------------------------\n5550.4: fetch 0.06(0.02+0.02) 0.02(0.01+0.00) -66.7%\n\nStill an impressive speedup as a percentage, but negligible in absolute\nterms. But that's on a local filesystem on a Linux machine. I'd worry\nmuch more about a system with a slow readdir(), e.g., due to NFS.\nSomebody's real-world NFS case[1] was what prompted us to do 0eeb077\n(index-pack: avoid excessive re-reading of pack directory, 2015-06-09).\n\nIt looks like I _did_ look into optimizing this into a single stat()\ncall in the thread at [1]. I completely forgot about that. I did find\nthere that naively using stat_validity() on a directory is racy, though\nI wonder if we could do something clever with gettimeofday() instead.\nIOW, the patches there only bothered to re-read when they saw the mtime\non the directory jump, which suffers from 1-second precision problems.\nBut if we instead compared the mtime to the current time, we could err\nin favor of re-reading the packs, and get false positives for at most 1\nsecond.\n\n[1] http://public-inbox.org/git/7FAE15F0A93C0144AD8B5FBD584E1C5519758FC3@C111KXTEMBX51.ERF.thomson.com/\n\n> I agree that the fallout from the inaccuracy of \"quick\" approach is\n> probably acceptable and the next \"fetch\" will correct it anyway, so\n> let's do the \"quick but inaccurate\" for now and perhaps cook it in\n> 'next' for a bit longer than other topics?\n\nI doubt that cooking in 'next' for longer will turn up anything useful.\nThe case we care about is the race between a repack and a fetch. We\nlived with the \"quick\" version of has_sha1_file() everywhere for 8\nyears. I only noticed the race on a hosting cluster which puts through\nmillions of operations per day (I could in theory test the patch on that\nsame cluster, but we actually don't do very many fetches).\n\n-Peff\n"},{"id":"304288","messageId":"xmqqeg3ex4qz.fsf@gitster.mtv.corp.google.com","threadId":"44292","inReplyTo":"20161014185953.k4b5xwihlgvxurjc@sigill.intra.peff.net","subject":"Re: [PATCH] fetch: use \"quick\" has_sha1_file for tag following","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2016-10-17T17:30:28Z","receivedAt":"2016-10-17T17:30:37Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> Still an impressive speedup as a percentage, but negligible in absolute\n> terms. But that's on a local filesystem on a Linux machine. I'd worry\n> much more about a system with a slow readdir(), e.g., due to NFS.\n> Somebody's real-world NFS case[1] was what prompted us to do 0eeb077\n> (index-pack: avoid excessive re-reading of pack directory, 2015-06-09).\n\nYes.\n\n> It looks like I _did_ look into optimizing this into a single stat()\n> call in the thread at [1]. I completely forgot about that. I did find\n> there that naively using stat_validity() on a directory is racy, though\n> I wonder if we could do something clever with gettimeofday() instead.\n\nIt feels funny to hear an idea to compare fs timestamp with gettimeofday\nimmedately after hearing the word NFS, though ;-).\n\n>> I agree that the fallout from the inaccuracy of \"quick\" approach is\n>> probably acceptable and the next \"fetch\" will correct it anyway, so\n>> let's do the \"quick but inaccurate\" for now and perhaps cook it in\n>> 'next' for a bit longer than other topics?\n>\n> I doubt that cooking in 'next' for longer will turn up anything useful.\n> The case we care about is the race between a repack and a fetch. We\n> lived with the \"quick\" version of has_sha1_file() everywhere for 8\n> years.\n\nA very convincing argument. I stand corrected.\n\nThanks.\n\n\n"},{"id":"304327","messageId":"20161018102813.mctfmrgljcxujkc7@sigill.intra.peff.net","threadId":"44292","inReplyTo":"xmqqeg3ex4qz.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH] fetch: use \"quick\" has_sha1_file for tag following","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-18T10:28:13Z","receivedAt":"2016-10-18T10:28:21Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Oct 17, 2016 at 10:30:28AM -0700, Junio C Hamano wrote:\n\n> > It looks like I _did_ look into optimizing this into a single stat()\n> > call in the thread at [1]. I completely forgot about that. I did find\n> > there that naively using stat_validity() on a directory is racy, though\n> > I wonder if we could do something clever with gettimeofday() instead.\n> \n> It feels funny to hear an idea to compare fs timestamp with gettimeofday\n> immedately after hearing the word NFS, though ;-).\n\nYeah, I had a funny feeling in my stomach as I wrote that.\n\nWhat you really want to know is the current filesystem time. You'd\nprobably have to do something gross like creating a new file and then\ncomparing its timestamp. In theory you'd only have to do that _once_,\nand then as long as the pack directory wasn't changing, you could say \"I\ndon't know what time it is now, but I know it is at least time X, and I\nknow that X is greater than Y, the pack directory timestamp, therefore\nthe pack directory hasn't changed since I last looked\".\n\nThat assumes monotonic clocks, but we basically already do so for the\nracy-git checks, I think.\n\nI dunno. It feels...complicated. And bad to require writing to the\nrepository for what would otherwise be a read-only operation. But I\ndon't see any fundamental reason it could not work.\n\n-Peff\n"}]}