{"thread":{"id":"38713","subject":"Slow git pushes: sitting 1 minute in pack-objects","startedAt":"2015-03-05T21:03:07Z","lastAt":"2015-03-19T21:07:31Z","messageCount":8,"participants":["Stephen Morton","Duy Nguyen","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"257105","messageId":"CAH8BJxH1uVv9J7yLx1D4GRPKfWYqDw8SRFZKGR_yhjcoTCCT2g@mail.gmail.com","threadId":"38713","inReplyTo":null,"subject":"Slow git pushes: sitting 1 minute in pack-objects","fromName":"Stephen Morton","fromEmail":"stephen.c.morton@gmail.com","sentAt":"2015-03-05T21:03:07Z","receivedAt":"2015-03-05T21:03:07Z","isPatch":false,"sender":{"key":"stephen.c.morton@gmail.com","avatar":"https://gravatar.com/avatar/3b826f06cabc070cbd5d53071880caad8badc3b29e0789b510353faca59ffb7b?d=mp&s=160"},"body":"(Apologies, after a day I'm cross-posting from git.users. I think the question\nis maybe too technical for that group.)\n\nI'm experiencing very slow git pushes. On the order of 1 minute to push a\ntrivial one-line change. When I set GIT_TRACE=1, I see that it seems to be\ntaking a lot of time in the pack-objects phase.\n\nOthers are not seeing this with the same repo, but I'm the only one working\nin a VM.\n\n```\n~/ws/git/repo.1/repo > date; git push mortons; date\nWed Mar 4 15:03:11 EST 2015\n15:03:11.086758 git.c:349 trace: built-in: git 'push' 'mortons'\n15:03:11.126665 run-command.c:341 trace: run_command: 'ssh' '-p'\n'7999' 'git@privacy.privacy' 'git-receive-pack\n'\\''~mortons/repo.git'\\'''\n15:03:20.383341 run-command.c:341 trace: run_command:\n'pack-objects' '--all-progress-implied' '--revs' '--stdout' '--thin'\n'--delta-base-offset' '--progress'\n15:03:20.383945 exec_cmd.c:134 trace: exec: 'git'\n'pack-objects' '--all-progress-implied' '--revs' '--stdout' '--thin'\n'--delta-base-offset' '--progress'\n15:03:20.385168 git.c:349 trace: built-in: git\n'pack-objects' '--all-progress-implied' '--revs' '--stdout' '--thin'\n'--delta-base-offset' '--progress'\nCounting objects: 4, done.\nDelta compression using up to 8 threads.\nCompressing objects: 100% (4/4), done.\nWriting objects: 100% (4/4), 20.86 KiB | 0 bytes/s, done.\nTotal 4 (delta 0), reused 0 (delta 0)\nTo ssh://git@privacy.privacy:7999/~mortons/repo.git\n 5fe662f..a137bda my_branch -> my_branch\nWed Mar 4 15:04:22 EST 2015\n\n```\n\nAfter it was slow at first, I tried setting these which did not help\n\nrepack.writebitmaps=true\npack.windowmemory=100m\n\n\n\nDetails:\ngit version 2.1.4\nOS: CentOS 6.6 64-bit in a VM.\nrepo size: huge. 6 GB .git directory, around 800 MB working tree.\nVM has 8 MB RAM and 8 cores.\nCPU: i7, 8 core (4 cores hyperthreaded)\n\nIt is an ext4 filesystem on the guest linux drive.\n On the host side, it is a .vmdk file and the virtualization software used is\nvirtualbox. While the drive is dynamically allocated, after I ran into\nthis issue,\n I used fallocate to create a 50GB dummy file and then delete it to\nensure that\nthere was headroom in the drive and that dynamic allocation slowness was not the\nissue, and subsequent pushes were still slow.\n I have not experienced any filesystem slowness issues in the\nmonths I've been using this vm.\n\n\nAny ideas? I'm evaluating a move to git and this is the kind of thing\nthat could derail it.\nThanks,\n\nStephen\n"},{"id":"257120","messageId":"CACsJy8CKdcHSNEpRZDTtR36Xcv+SF2tUizNjXd_sAb1eUBgTzA@mail.gmail.com","threadId":"38713","inReplyTo":"CAH8BJxH1uVv9J7yLx1D4GRPKfWYqDw8SRFZKGR_yhjcoTCCT2g@mail.gmail.com","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2015-03-06T00:25:45Z","receivedAt":"2015-03-06T00:25:45Z","isPatch":false,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Fri, Mar 6, 2015 at 4:03 AM, Stephen Morton\n wrote:\n> I'm experiencing very slow git pushes. On the order of 1 minute to push a\n> trivial one-line change. When I set GIT_TRACE=1, I see that it seems to be\n> taking a lot of time in the pack-objects phase.\n>\n> Others are not seeing this with the same repo, but I'm the only one working\n> in a VM.\n>\n> ...\n>\n> Details:\n> git version 2.1.4\n> OS: CentOS 6.6 64-bit in a VM.\n> repo size: huge. 6 GB .git directory, around 800 MB working tree.\n> VM has 8 MB RAM and 8 cores.\n\nIs it 8 GB or MB RAM?\n\n> CPU: i7, 8 core (4 cores hyperthreaded)\n-- \nDuy\n"},{"id":"257121","messageId":"CAH8BJxFF9TMDo=s+omcsMx2qEReHKEXb6snrsuKSQekOhPY+ag@mail.gmail.com","threadId":"38713","inReplyTo":"CACsJy8CKdcHSNEpRZDTtR36Xcv+SF2tUizNjXd_sAb1eUBgTzA@mail.gmail.com","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Stephen Morton","fromEmail":"stephen.c.morton@gmail.com","sentAt":"2015-03-06T00:37:43Z","receivedAt":"2015-03-06T00:37:43Z","isPatch":false,"sender":{"key":"stephen.c.morton@gmail.com","avatar":"https://gravatar.com/avatar/3b826f06cabc070cbd5d53071880caad8badc3b29e0789b510353faca59ffb7b?d=mp&s=160"},"body":"8GB of RAM.\n\nSorry, typo.\n\nSteve\n\n\nOn Thu, Mar 5, 2015 at 7:25 PM, Duy Nguyen wrote:\n> On Fri, Mar 6, 2015 at 4:03 AM, Stephen Morton\n> wrote:\n>> I'm experiencing very slow git pushes. On the order of 1 minute to push a\n>> trivial one-line change. When I set GIT_TRACE=1, I see that it seems to be\n>> taking a lot of time in the pack-objects phase.\n>>\n>> Others are not seeing this with the same repo, but I'm the only one working\n>> in a VM.\n>>\n>> ...\n>>\n>> Details:\n>> git version 2.1.4\n>> OS: CentOS 6.6 64-bit in a VM.\n>> repo size: huge. 6 GB .git directory, around 800 MB working tree.\n>> VM has 8 MB RAM and 8 cores.\n>\n> Is it 8 GB or MB RAM?\n>\n>> CPU: i7, 8 core (4 cores hyperthreaded)\n> --\n> Duy\n"},{"id":"257368","messageId":"20150309075302.GB31866@peff.net","threadId":"38713","inReplyTo":"CAH8BJxH1uVv9J7yLx1D4GRPKfWYqDw8SRFZKGR_yhjcoTCCT2g@mail.gmail.com","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-03-09T07:53:02Z","receivedAt":"2015-03-09T07:53:02Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Mar 05, 2015 at 04:03:07PM -0500, Stephen Morton wrote:\n\n> I'm experiencing very slow git pushes. On the order of 1 minute to push a\n> trivial one-line change. When I set GIT_TRACE=1, I see that it seems to be\n> taking a lot of time in the pack-objects phase.\n\nCan you tell what pack-objects is doing? Perhaps \"strace -f -tt\" might\nhelp. Or even just \"time git push\", which will tell us whether we're\nspinning on CPU or something else.\n\nIf you watch the progress meter, where does it spend its time? In\n\"counting objects\", \"compressing objects\", or \"writing objects\"? Or\nafter that?\n\nYou said the repo is big. Is it reasonably packed (try running `git\ngc`). Pack-objects may look at objects that you know the other side has\nin order to create deltas against them. If you have some crazy situation\n(e.g., you have several thousand packfiles) that can slow down object\naccess quite a bit. A minute is more than I would expect, but if VFS\noperations in your VM are slow, that could be it.\n\n-Peff\n"},{"id":"257437","messageId":"CAH8BJxHQnMkXq1J_wMi2KktTH5uHjj+vd69ihXuYGRfq9cOt=g@mail.gmail.com","threadId":"38713","inReplyTo":"20150309075302.GB31866@peff.net","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Stephen Morton","fromEmail":"stephen.c.morton@gmail.com","sentAt":"2015-03-10T01:37:25Z","receivedAt":"2015-03-10T01:37:25Z","isPatch":false,"sender":{"key":"stephen.c.morton@gmail.com","avatar":"https://gravatar.com/avatar/3b826f06cabc070cbd5d53071880caad8badc3b29e0789b510353faca59ffb7b?d=mp&s=160"},"body":"Thanks Peff,\n\nI've done an strace and here's what I see. I'll try to put relevant\ninformation in as legible a form as possible. The operation is\ncpu-bound on a single core (note that yes, delta compression is using\n8 threads. so that's obviously not the bottleneck) for the duration of\nthe pack-objects.\n\nTiming is tough, because it's slower when straced.\n\nI don't know if it matters, but this push is going to a fork on the\nremote end most of whose objects are in the objects/info/alternatives\nlocation. (Which is still on the local drive of the remote, not a\nnetwork drive or anything like that.)\n\n1.\n > GIT_TRACE=1 time time git push\n12:21:28.980410 git.c:349 trace: built-in: git 'push'\n12:21:29.099547 run-command.c:341 trace: run_command: 'ssh' '-p'\n'7999' 'git@server.privacy' 'git-receive-pack\n'\\''~smorton/panos.git'\\'''\n12:21:42.863968 run-command.c:341 trace: run_command:\n'pack-objects' '--all-progress-implied' '--revs' '--stdout' '--thin'\n'--delta-base-offset' '--progress'\n12:21:42.871170 exec_cmd.c:134 trace: exec: 'git'\n'pack-objects' '--all-progress-implied' '--revs' '--stdout' '--thin'\n'--delta-base-offset' '--progress'\n12:21:42.907783 git.c:349 trace: built-in: git\n'pack-objects' '--all-progress-implied' '--revs' '--stdout' '--thin'\n'--delta-base-offset' '--progress'\n\n2. At this point, \"git pack-objects\" is forked\n\n3. Not sure how long this part takes. It takes 1/3 - 1/2 of the time\nwhen straced, but I think it's much less, as little as 10s when not\nstraced.\nIt then reads a bunch of what look like objects from filehandle 0\n(presumably stdin, read from the remote end?)\nIt then tries to lstat() these filenames in .git/\n./git/refs/, .git/heads/, etc. It always fails ENOENT.\nIt fails some 120,000 times. This could be a problem. Though I haven't\nchecked to see if this happens on a fast push on another machine.\n\nThis takes a lot of time when straced, but I think less time when not straced.\n\n4. Then it just sits there for almost 1 minute. It uses up almost 100%\nof a single core during this period. It spends a lot of time running\nlots of brk() (memory allocation) commands and then getting (polled\nby?) a SIGALRM every 1s.\nAbout 5.5+ GB (about the repo size) of VIRT memory is allocated. Only\nabout 400M is ever RES.\n\n\n5. Then we get to the \"Counting objects\" phase.\nNote the number of threads specified: so it\n\nCounting objects: 4, done.\nDelta compression using up to 8 threads.\nCompressing objects: 100% (4/4), done.\n...\n\n\n6. Time. Note the 121,000 pagefaults\n\n46.08user 0.67system 0:49.47elapsed 94%CPU (0avgtext+0avgdata\n1720240maxresident)k\n0inputs+16outputs (0major+121199minor)pagefaults 0swaps\n\nSteve\n\n\n\nOn Mon, Mar 9, 2015 at 3:53 AM, Jeff King wrote:\n> On Thu, Mar 05, 2015 at 04:03:07PM -0500, Stephen Morton wrote:\n>\n>> I'm experiencing very slow git pushes. On the order of 1 minute to push a\n>> trivial one-line change. When I set GIT_TRACE=1, I see that it seems to be\n>> taking a lot of time in the pack-objects phase.\n>\n> Can you tell what pack-objects is doing? Perhaps \"strace -f -tt\" might\n> help. Or even just \"time git push\", which will tell us whether we're\n> spinning on CPU or something else.\n>\n> If you watch the progress meter, where does it spend its time? In\n> \"counting objects\", \"compressing objects\", or \"writing objects\"? Or\n> after that?\n>\n> You said the repo is big. Is it reasonably packed (try running `git\n> gc`). Pack-objects may look at objects that you know the other side has\n> in order to create deltas against them. If you have some crazy situation\n> (e.g., you have several thousand packfiles) that can slow down object\n> access quite a bit. A minute is more than I would expect, but if VFS\n> operations in your VM are slow, that could be it.\n>\n> -Peff\n"},{"id":"257822","messageId":"20150316221532.GA16679@peff.net","threadId":"38713","inReplyTo":"CAH8BJxHQnMkXq1J_wMi2KktTH5uHjj+vd69ihXuYGRfq9cOt=g@mail.gmail.com","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-03-16T22:15:33Z","receivedAt":"2015-03-16T22:15:33Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Mar 09, 2015 at 09:37:25PM -0400, Stephen Morton wrote:\n\n> 3. Not sure how long this part takes. It takes 1/3 - 1/2 of the time\n> when straced, but I think it's much less, as little as 10s when not\n> straced.\n> It then reads a bunch of what look like objects from filehandle 0\n> (presumably stdin, read from the remote end?)\n> It then tries to lstat() these filenames in .git/\n> ./git/refs/, .git/heads/, etc. It always fails ENOENT.\n> It fails some 120,000 times. This could be a problem. Though I haven't\n> checked to see if this happens on a fast push on another machine.\n\nHmm. The \"push\" process must feed the set of object boundaries to\n\"pack-objects\" so it knows what to pack (i.e., what we want to send, and\nwhat the other side has).\n\n120,000 is an awfully large number of objects to be pass there, though.\nDoes the repo you are pushing to by any chance have an extremely large\nnumber of refs (e.g., on the order of 120K tags)?\n\nCan you try building git with this patch which would tell us more about\nwhere those objects are coming from?\n\ndiff --git a/send-pack.c b/send-pack.c\nindex 9d2b0c5..17ace1f 100644\n--- a/send-pack.c\n+++ b/send-pack.c\n@@ -74,10 +74,19 @@ static int pack_objects(int fd, struct ref *refs, struct sha1_array *extra, stru\n \t * We feed the pack-objects we just spawned with revision\n \t * parameters by writing to the pipe.\n \t */\n+\twarning(\"feeding %d .have objects\", extra->nr);\n \tfor (i = 0; i < extra->nr; i++)\n \t\tif (!feed_object(extra->sha1[i], po.in, 1))\n \t\t\tbreak;\n \n+\t{\n+\t\tstruct ref *p;\n+\t\tint count = 0;\n+\t\tfor (p = refs; p; p = p->next)\n+\t\t\tcount++;\n+\t\twarning(\"feeding %d refs\", count);\n+\t}\n+\n \twhile (refs) {\n \t\tif (!is_null_sha1(refs->old_sha1) &&\n \t\t !feed_object(refs->old_sha1, po.in, 1))\n\n> 4. Then it just sits there for almost 1 minute. It uses up almost 100%\n> of a single core during this period. It spends a lot of time running\n> lots of brk() (memory allocation) commands and then getting (polled\n> by?) a SIGALRM every 1s.\n> About 5.5+ GB (about the repo size) of VIRT memory is allocated. Only\n> about 400M is ever RES.\n\nThe SIGALRM is normal. That's the progress code checking in every 2\nseconds to see if there's anything to print. My guess is that the\nallocation is probably coming as part of the \"preferred base\" code. This\nis a fancy term for \"stuff we are not going to send, but which we could\nuse as delta bases for objects we are sending\".\n\nDoes the patch below speed things up (it is not a good thing to do in\ngeneral, but would let us know if that is the problematic area):\n\ndiff --git a/builtin/pack-objects.c b/builtin/pack-objects.c\nindex d816587..c90a352 100644\n--- a/builtin/pack-objects.c\n+++ b/builtin/pack-objects.c\n@@ -2307,7 +2307,6 @@ static void show_object(struct object *obj,\n \n static void show_edge(struct commit *commit)\n {\n-\tadd_preferred_base(commit->object.sha1);\n }\n \n struct in_pack_object {\n\nIf not, then the slowdown may come before we even get there, and\npossibly this patch would help:\n\ndiff --git a/builtin/pack-objects.c b/builtin/pack-objects.c\nindex d816587..473c0a3 100644\n--- a/builtin/pack-objects.c\n+++ b/builtin/pack-objects.c\n@@ -2531,6 +2531,8 @@ static void get_object_list(int ac, const char **av)\n \t\t\t}\n \t\t\tdie(\"not a rev '%s'\", line);\n \t\t}\n+\t\tif (*line == '^')\n+\t\t\tcontinue;\n \t\tif (handle_revision_arg(line, &revs, flags, REVARG_CANNOT_BE_FILENAME))\n \t\t\tdie(\"bad revision '%s'\", line);\n \t}\n\nThose are all rather blunt debugging methods, but hopefully it can get\nus a sense of where the time is going.\n\n-Peff\n"},{"id":"258048","messageId":"CAH8BJxErCMk1JQMMKm9_j4bckB7bEVB+r28_zYovE=pe1nUa_Q@mail.gmail.com","threadId":"38713","inReplyTo":"20150316221532.GA16679@peff.net","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Stephen Morton","fromEmail":"stephen.c.morton@gmail.com","sentAt":"2015-03-19T20:31:36Z","receivedAt":"2015-03-19T20:31:36Z","isPatch":false,"sender":{"key":"stephen.c.morton@gmail.com","avatar":"https://gravatar.com/avatar/3b826f06cabc070cbd5d53071880caad8badc3b29e0789b510353faca59ffb7b?d=mp&s=160"},"body":"On Mon, Mar 16, 2015 at 6:15 PM, Jeff King wrote:\n> On Mon, Mar 09, 2015 at 09:37:25PM -0400, Stephen Morton wrote:\n>\n>> 3. Not sure how long this part takes. It takes 1/3 - 1/2 of the time\n>> when straced, but I think it's much less, as little as 10s when not\n>> straced.\n>> It then reads a bunch of what look like objects from filehandle 0\n>> (presumably stdin, read from the remote end?)\n>> It then tries to lstat() these filenames in .git/\n>> ./git/refs/, .git/heads/, etc. It always fails ENOENT.\n>> It fails some 120,000 times. This could be a problem. Though I haven't\n>> checked to see if this happens on a fast push on another machine.\n>\n> Hmm. The \"push\" process must feed the set of object boundaries to\n> \"pack-objects\" so it knows what to pack (i.e., what we want to send, and\n> what the other side has).\n>\n> 120,000 is an awfully large number of objects to be pass there, though.\n> Does the repo you are pushing to by any chance have an extremely large\n> number of refs (e.g., on the order of 120K tags)?\n\n\nNo. There are on the order of 9,500 refs (mostly tags) but nowhere near 120k.\n\n\n\n>\n> Can you try building git with this patch which would tell us more about\n> where those objects are coming from?\n\n\n \n\n> Those are all rather blunt debugging methods, but hopefully it can get\n> us a sense of where the time is going.\n>\n> -Peff\n\n\nThanks Peff,\n\n\nI haven't tried your patch, but I tried to backtrack a bit and\ndouble-check that the problem always happened in a fresh clone with no\nother modifications.\n\nIt did _not_ happen in a new clone --a push took just 5s -- and I\nthink the culprit could have been \"repack.writebitmaps=true\". Although\nI had thought writebitmaps was not originally enabled, I now suspect\nthat it was. Let me follow up on that first, before I recompile git\nwith your changes.\n\n\nThanks again, I really appreciate the help.\n\nSteve\n"},{"id":"258055","messageId":"20150319210731.GA8363@peff.net","threadId":"38713","inReplyTo":"CAH8BJxErCMk1JQMMKm9_j4bckB7bEVB+r28_zYovE=pe1nUa_Q@mail.gmail.com","subject":"Re: Slow git pushes: sitting 1 minute in pack-objects","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-03-19T21:07:31Z","receivedAt":"2015-03-19T21:07:31Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Mar 19, 2015 at 04:31:36PM -0400, Stephen Morton wrote:\n\n> > Hmm. The \"push\" process must feed the set of object boundaries to\n> > \"pack-objects\" so it knows what to pack (i.e., what we want to send, and\n> > what the other side has).\n> >\n> > 120,000 is an awfully large number of objects to be pass there, though.\n> > Does the repo you are pushing to by any chance have an extremely large\n> > number of refs (e.g., on the order of 120K tags)?\n> \n> No. There are on the order of 9,500 refs (mostly tags) but nowhere near 120k.\n\nI think you mentioned that it uses alternates to share objects with\nother repos. Does the repository (or repositories) pointed to by the\nalternates file have a large number of refs (especially distinct refs,\nas I think modern git will squelch duplicate sha1s).\n\n> It did _not_ happen in a new clone --a push took just 5s -- and I\n> think the culprit could have been \"repack.writebitmaps=true\". Although\n> I had thought writebitmaps was not originally enabled, I now suspect\n> that it was. Let me follow up on that first, before I recompile git\n> with your changes.\n\nIt's certainly possible that bitmaps have an impact here. They should\nnot contribute to the 120K objects being passed to pack-objects, but\nit's possible that size is a red herring (or possibly the number of\nobjects is choking something in the bitmap code path that does not have\nproblems otherwise).\n\n-Peff\n"}]}