{"thread":{"id":"53601","subject":"Huge push upload despite only having a tiny change","startedAt":"2020-06-02T19:21:27Z","lastAt":"2020-06-03T20:39:36Z","messageCount":6,"participants":["Elijah Newren","Derrick Stolee","Jonathan Nieder","Junio C Hamano"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"399046","messageId":"CABPp-BEswHLhymQ1_07g3qqu=7kFR3eQyAHR0qMgSvi6THy=zQ@mail.gmail.com","threadId":"53601","inReplyTo":null,"subject":"Huge push upload despite only having a tiny change","fromName":"Elijah Newren","fromEmail":"newren@gmail.com","sentAt":"2020-06-02T19:21:13Z","receivedAt":"2020-06-02T19:21:27Z","isPatch":false,"sender":{"key":"newren@gmail.com","avatar":"https://avatars.githubusercontent.com/u/5455730?v=4"},"body":"Hi,\n\nI had a user report that two nearly identical pushes (the second being\nan amended commit of the first) took dramatically differing amounts of\ntime and amount of data uploaded (from 4.5 seconds and about 21k\nuploaded, to 223 seconds and over 100 MB uploaded).\n\nI'm curious if this might be a known issue; it sounds similar to some\npush protocol discussion I remember from the contributor's summit (but\nI don't know anything on the protocol side and tend to work on other\nthings during protocol discussion).  If this does sound like a known\nissue, does anyone have links to some relevant discussion I can read\nup on (and perhaps pass long to this user)?  If it doesn't sound like\na known issue, what other things would be useful for me to dig up?\n\nAdditional details:\n* Both pushes involved cases where the user had a single commit that\nthe server didn't.\n* The parent of the commit that needed to be pushed was the same in both cases.\n* The commit in question was small; modifying either 13 or 15 lines of\ntwo files that were each less than about 8k in size.\n* The user was pushing up a new branch each time, but the new branch\nwas closely related to an existing branch (i.e. had all but a few\ncommits of history in common)\n* The user was two commits behind the closely-related branch at the\ntime of the first push, and 10 commits behind at the time of the\nsecond push.  Running format-patch on these 10 commits that were on\nthe server at the time shows their size is at most about ~55 k.\n* The server has a huge number of refs; about 470k of them (most of\nthem related to code reviews).\n* The server was running Gerrit 3.1.4 (i.e. jgit).\n* The user was using a version of git based off master from a few\nweeks ago, in particular, with a few changes on top of commit\nb994622632 (\"The eighth batch\", 2020-05-08).  I don't think the few\ninternal changes could affect anything here, but those changes were:\n(1) making features.experimental default to true (which only turns on\ntwo fetch settings as far as I can tell), (2) making\nmerge.directoryRenames default to true, and (3) setting a few trace2.*\nconfig settings by default.\n\nThanks,\nElijah\n"},{"id":"399048","messageId":"29e6c05e-2d79-d2ac-a033-dab6342ebcaa@gmail.com","threadId":"53601","inReplyTo":"CABPp-BEswHLhymQ1_07g3qqu=7kFR3eQyAHR0qMgSvi6THy=zQ@mail.gmail.com","subject":"Re: Huge push upload despite only having a tiny change","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2020-06-02T19:40:29Z","receivedAt":"2020-06-02T19:40:32Z","isPatch":false,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 6/2/2020 3:21 PM, Elijah Newren wrote:\n> * The user was two commits behind the closely-related branch at the\n> time of the first push, and 10 commits behind at the time of the\n> second push.  Running format-patch on these 10 commits that were on\n> the server at the time shows their size is at most about ~55 k.\n\nThis is most-likely the difference, since the pack-objects algorithm\nonly looks at the _boundary_ between the server's commits and the\ncommits-to-push. This also could have dramatically changed the delta-base\nmatches.\n\nDo you have exact object counts? It would help to know if somehow the\nobject discovery algorithm is at fault or the delta-base algorithm\nis to blame.\n\nFor instance, `pack.useSparse` was enabled by default this release,\nand has some opportunity to push extra objects. See [1] for more\ndetails on both the \"boundary\" description (the \"commit frontier\")\nbut also how that option changes the algorithm.\n\nThe only case I know of that could lead to sending extra objects\n(that was not the case before) is described in t5322-pack-objects-sparse.sh\nand 4f6d26b1 (list-objects: consume sparse tree walk, 2019-01-16).\nIt involves doing a full _copy_ of a tree from one position to\nanother, without \"disturbing\" the parent of the original tree.\n\n(I mean: copy directory A/B to C/D and make sure nothing is\ndifferent in directory A.)\n\nHowever, if these two pushes were with the same config setting,\nI'm not sure what could have changed between the pushes to hit\nthis very narrow case.\n\nThanks,\n-Stolee\n\n\n[1] https://devblogs.microsoft.com/devops/exploring-new-frontiers-for-git-push-performance/\n"},{"id":"399058","messageId":"CABPp-BGH=uqOP2x5w4ghLBv1sUiyKwdj1ox8kJKrELOp_OhudQ@mail.gmail.com","threadId":"53601","inReplyTo":"29e6c05e-2d79-d2ac-a033-dab6342ebcaa@gmail.com","subject":"Re: Huge push upload despite only having a tiny change","fromName":"Elijah Newren","fromEmail":"newren@gmail.com","sentAt":"2020-06-03T01:35:13Z","receivedAt":"2020-06-03T01:35:28Z","isPatch":false,"sender":{"key":"newren@gmail.com","avatar":"https://avatars.githubusercontent.com/u/5455730?v=4"},"body":"On Tue, Jun 2, 2020 at 12:40 PM Derrick Stolee <stolee@gmail.com> wrote:\n>\n> On 6/2/2020 3:21 PM, Elijah Newren wrote:\n> > * The user was two commits behind the closely-related branch at the\n> > time of the first push, and 10 commits behind at the time of the\n> > second push.  Running format-patch on these 10 commits that were on\n> > the server at the time shows their size is at most about ~55 k.\n>\n> This is most-likely the difference, since the pack-objects algorithm\n> only looks at the _boundary_ between the server's commits and the\n> commits-to-push. This also could have dramatically changed the delta-base\n> matches.\n>\n> Do you have exact object counts? It would help to know if somehow the\n> object discovery algorithm is at fault or the delta-base algorithm\n> is to blame.\n\nOutput from the users' terminal for the two different runs, just\nredacting URLs.  The first push was:\n\nEnumerating objects: 23, done.\nCounting objects: 100% (23/23), done.\nDelta compression using up to 16 threads\nCompressing objects: 100% (7/7), done.\nWriting objects: 100% (12/12), 952 bytes | 952.00 KiB/s, done.\nTotal 12 (delta 5), reused 0 (delta 0), pack-reused 0\nremote: Resolving deltas: 100% (5/5)\nremote: Processing changes: refs: 1, new: 1, done\nremote: commit 5efcf04: warning: subject >50 characters; use shorter\nfirst paragraph\nremote:\nremote: SUCCESS\nremote:\nremote:   https://gerrit.internal.site/c/path/to/repo/+/341489 Remove\nambiguous method from ArtifactProducerPeeringService [NEW]\nremote:\nTo gerrit.internal.site:path/to/repo.git\n * [new branch]                HEAD -> refs/for/develop\n\nThe second was:\n\nEnumerating objects: 325816, done.\nCounting objects: 100% (266559/266559), done.\nDelta compression using up to 16 threads\nCompressing objects: 100% (102457/102457), done.\nWriting objects: 100% (257630/257630), 102.88 MiB | 619.00 KiB/s, done.\nTotal 257630 (delta 122169), reused 218776 (delta 87259), pack-reused 0\nremote: Resolving deltas: 100% (122169/122169)\nremote: Processing changes: refs: 1, updated: 1, done\nremote: commit 360a266: warning: subject >50 characters; use shorter\nfirst paragraph\nremote:\nremote: SUCCESS\nremote:\nremote:   https://gerrit.internal.site/c/path/to/repo/+/341489 Remove\nambiguous method from ArtifactProducerPeeringService\nremote:\nTo gerrit.internal.site:path/to/repo.git\n * [new branch]                HEAD -> refs/for/develop\n\n> For instance, `pack.useSparse` was enabled by default this release,\n> and has some opportunity to push extra objects. See [1] for more\n> details on both the \"boundary\" description (the \"commit frontier\")\n> but also how that option changes the algorithm.\n>\n> The only case I know of that could lead to sending extra objects\n> (that was not the case before) is described in t5322-pack-objects-sparse.sh\n> and 4f6d26b1 (list-objects: consume sparse tree walk, 2019-01-16).\n> It involves doing a full _copy_ of a tree from one position to\n> another, without \"disturbing\" the parent of the original tree.\n>\n> (I mean: copy directory A/B to C/D and make sure nothing is\n> different in directory A.)\n>\n> However, if these two pushes were with the same config setting,\n> I'm not sure what could have changed between the pushes to hit\n> this very narrow case.\n\nSo, after a day of attempting to figure out how to debug, I found out\nwe had a backup of the server between the first and second pushes and\nfairly close to the second push.  I was able to launch a separate VM\nof that backup, and then attempt to make a local repo that I hoped\nmimic what the user had.  I can't duplicate the 100MB push (which is\nabout 25000x bigger than expected) as the user did, but I can with\nsome tweaking state that the push size should be closer to ~2.5 KB and\nI can readly duplicate pushes in the 4-6 MB range -- i.e. about 1000x\nbigger than expected.  pack.useSparse affects things, but not much.\nSo, some output of my own duplication attempts:\n\nFirst, if I do a git fetch of the 'develop' branch (I can even nuke\n.git/FETCH_HEAD afterwards; it only matters that I have the history\nlocally) from the place I'm pushing to, then the push size is tiny as\nexpected:\n\n<Go to server, use rsync to make a pristine copy of repo>\n<Go to server, rsync repo from pristine state, then on my laptop:>\n\n$ git fetch git_over_ssh_url develop\n$ rm .git/FETCH_HEAD\n$ time git push git_over_ssh_url mike-push:refs/for/develop\nEnumerating objects: 37, done.\nCounting objects: 100% (37/37), done.\nDelta compression using up to 8 threads\nCompressing objects: 100% (11/11), done.\nWriting objects: 100% (22/22), 2.54 KiB | 2.54 MiB/s, done.\nTotal 22 (delta 7), reused 14 (delta 1), pack-reused 0\nremote: Checking connectivity: 22, done.\nTo git_over_ssh_url\n * [new branch]                mike-push -> refs/for/develop\n\nreal 0m13.044s\nuser 0m0.202s\nsys 0m0.146s\n\n<Remove the pack downloaded from the earlier fetch of develop>\n<Without this step, I always get small pushes:>\n$ ls -rt .git/objects/pack/ | tail -n 2 | xargs -n 1 -IPATH rm\n.git/objects/pack/PATH\n\n<Go to server, rsync repo from pristine state, then on my laptop:>\n$ time git push git_over_ssh_url mike-push:refs/for/develop\nEnumerating objects: 40785, done.\nCounting objects: 100% (20543/20543), done.\nDelta compression using up to 8 threads\nCompressing objects: 100% (9032/9032), done.\nWriting objects: 100% (16685/16685), 6.27 MiB | 208.00 KiB/s, done.\nTotal 16685 (delta 7103), reused 12412 (delta 3389), pack-reused 0\nremote: Resolving deltas: 100% (7103/7103), completed with 1864 local objects.\nremote: Checking connectivity: 22, done.\nTo git_over_ssh_url\n * [new branch]                mike-push -> refs/for/develop\n\nreal 0m59.703s\nuser 0m3.139s\nsys 0m0.735s\n\n<Also, this is only slightly affected by pack.useSparse...>\n<Go to server, rsync repo from pristine state, then on my laptop:>\n$ time git -c pack.useSparse=false push git_over_ssh_url\nmike-push:refs/for/develop\nEnumerating objects: 39891, done.\nCounting objects: 100% (18953/18953), done.\nDelta compression using up to 8 threads\nCompressing objects: 100% (7687/7687), done.\nWriting objects: 100% (14991/14991), 4.85 MiB | 228.00 KiB/s, done.\nTotal 14991 (delta 6665), reused 11301 (delta 3141), pack-reused 0\nremote: Resolving deltas: 100% (6665/6665), completed with 1939 local objects.\nremote: Checking connectivity: 22, done.\nTo git_over_ssh_url\n * [new branch]                mike-push -> refs/for/develop\n\nreal 0m49.295s\nuser 0m2.362s\nsys 0m0.592s\n\n\nFinally, you'll note that when I was reproducing, things were a bit\ndifferent than what Mike (the end user) was dealing with.  I was using\nvanilla git-2.27.0.  Also, on the server, I was using plain old\ngit-over-ssh, with the server running git-2.19.0.  However, I also\ntried it with gerrit (i.e. jgit) as the server and got identical\nnumbers for enumerating objects, counting objects, compressing\nobjects, and the size of the pushed data and the number of resolved\ndeltas was within 1% of the git-over-ssh case.  And that was also true\nboth with and without pack.useSparse.\n\nAny ideas?  Anything else I should try or provide data on?\n"},{"id":"399059","messageId":"20200603015314.GA253041@google.com","threadId":"53601","inReplyTo":"CABPp-BEswHLhymQ1_07g3qqu=7kFR3eQyAHR0qMgSvi6THy=zQ@mail.gmail.com","subject":"Re: Huge push upload despite only having a tiny change","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2020-06-03T01:53:14Z","receivedAt":"2020-06-03T01:53:20Z","isPatch":false,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"(cc: Jonathan Tan for \"git push\" discussion; Minh Thai for negotiate\n hook discussion)\nHi,\n\nElijah Newren wrote:\n\n> I had a user report that two nearly identical pushes (the second being\n> an amended commit of the first) took dramatically differing amounts of\n> time and amount of data uploaded (from 4.5 seconds and about 21k\n> uploaded, to 223 seconds and over 100 MB uploaded).\n\nYes, this is why I want push negotiation.  (It's been something we've\nbeen discussing for protocol v2 for push.)\n\nIf they fetch before they push, does that help?\n\n[...]\n> * The server was running Gerrit 3.1.4 (i.e. jgit).\n\nGerrit servers have the interesting property that many people are\npushing to the same Git repo.  (This is common in some other hosting\nscenarios such as Gitlab, but the most common case among Git users\nstill seems to be pushing to a repo you own.)\n\nWhen you push, because there's no negotiation phase, the only\ninformation we have about what is present on the server is what is in\nthe ref advertisement.  (We have remote-tracking branches which seem\npotentially useful, but we don't have a way to ask the server \"are\nthese objects you still have?\")  The ref advertisement describes the\n*current* state of all refs.  If I am pushing a new topic branch (in\nGerrit jargon, a new change for review) based on the *old* state of a\nbranch that has moved on, then we can only hope that some other ref\n(for example a tag) points to a recent enough state to give us a base\nfor what to upload.\n\nThere is one trick a server can use to mitigate this: advertise some\nrefs that don't exist!  If you advertise a ref \".have\", then Git\nwill understand that the server has that object but it is not an\nactual ref.  Gerrit uses this trick in its HackPushNegotiateHook[1]\nto advertise a few recent commits.\n\nAt $DAYJOB we ran into some clients where \"a few recent commits\" was\nnot sufficient to get to history that the client is aware of.  We\ntried changing it to do some exponential deepening, and that helped.\nWe should probably upstream that change for other Gerrit users.\n\nGerrit also advertises some other \".have\"s, for example for recent\nchanges by the same author in case you're uploading an amended\nversion.  That's less relevant here.\n\nBut fundamentally, this is something that cannot be addressed properly\nwithout improving the \"git push\" protocol (adding a negotiation\nphase).\n\nSummary: (1) try fetching first (2) let's improve\nHackPushNegotiateHook#advertiseRefs (3) let's improve \"git push\"\nprotocol to make this a problem of the past.\n\nThanks and hope that helps,\nJonathan\n\n[1] https://gerrit.googlesource.com/gerrit/+/e1f4fee1f3ce674f44cb9788e6798ff8522bb876/java/com/google/gerrit/server/git/receive/HackPushNegotiateHook.java#111\n"},{"id":"399061","messageId":"CABPp-BH9M-Rkq1YkNkJGqzu_z5poT4uS6Pk1f==ey+NLckiHTg@mail.gmail.com","threadId":"53601","inReplyTo":"20200603015314.GA253041@google.com","subject":"Re: Huge push upload despite only having a tiny change","fromName":"Elijah Newren","fromEmail":"newren@gmail.com","sentAt":"2020-06-03T02:36:46Z","receivedAt":"2020-06-03T02:37:01Z","isPatch":false,"sender":{"key":"newren@gmail.com","avatar":"https://avatars.githubusercontent.com/u/5455730?v=4"},"body":"Hi,\n\nOn Tue, Jun 2, 2020 at 6:53 PM Jonathan Nieder <jrnieder@gmail.com> wrote:\n>\n> (cc: Jonathan Tan for \"git push\" discussion; Minh Thai for negotiate\n>  hook discussion)\n> Hi,\n>\n> Elijah Newren wrote:\n>\n> > I had a user report that two nearly identical pushes (the second being\n> > an amended commit of the first) took dramatically differing amounts of\n> > time and amount of data uploaded (from 4.5 seconds and about 21k\n> > uploaded, to 223 seconds and over 100 MB uploaded).\n>\n> Yes, this is why I want push negotiation.  (It's been something we've\n> been discussing for protocol v2 for push.)\n>\n> If they fetch before they push, does that help?\n\nIn my attempts to reproduce which I assume are similar, yes it helps immensely.\n\n> [...]\n> > * The server was running Gerrit 3.1.4 (i.e. jgit).\n>\n> Gerrit servers have the interesting property that many people are\n> pushing to the same Git repo.  (This is common in some other hosting\n> scenarios such as Gitlab, but the most common case among Git users\n> still seems to be pushing to a repo you own.)\n>\n> When you push, because there's no negotiation phase, the only\n> information we have about what is present on the server is what is in\n> the ref advertisement.  (We have remote-tracking branches which seem\n> potentially useful, but we don't have a way to ask the server \"are\n> these objects you still have?\")  The ref advertisement describes the\n> *current* state of all refs.  If I am pushing a new topic branch (in\n> Gerrit jargon, a new change for review) based on the *old* state of a\n> branch that has moved on, then we can only hope that some other ref\n> (for example a tag) points to a recent enough state to give us a base\n> for what to upload.\n>\n> There is one trick a server can use to mitigate this: advertise some\n> refs that don't exist!  If you advertise a ref \".have\", then Git\n> will understand that the server has that object but it is not an\n> actual ref.  Gerrit uses this trick in its HackPushNegotiateHook[1]\n> to advertise a few recent commits.\n>\n> At $DAYJOB we ran into some clients where \"a few recent commits\" was\n> not sufficient to get to history that the client is aware of.  We\n> tried changing it to do some exponential deepening, and that helped.\n> We should probably upstream that change for other Gerrit users.\n>\n> Gerrit also advertises some other \".have\"s, for example for recent\n> changes by the same author in case you're uploading an amended\n> version.  That's less relevant here.\n>\n> But fundamentally, this is something that cannot be addressed properly\n> without improving the \"git push\" protocol (adding a negotiation\n> phase).\n>\n> Summary: (1) try fetching first (2) let's improve\n> HackPushNegotiateHook#advertiseRefs (3) let's improve \"git push\"\n> protocol to make this a problem of the past.\n>\n> Thanks and hope that helps,\n> Jonathan\n>\n> [1] https://gerrit.googlesource.com/gerrit/+/e1f4fee1f3ce674f44cb9788e6798ff8522bb876/java/com/google/gerrit/server/git/receive/HackPushNegotiateHook.java#111\n\nYes, this helps a lot.  Thanks for the pointers and explanations!\n"},{"id":"399090","messageId":"xmqqpnafriin.fsf@gitster.c.googlers.com","threadId":"53601","inReplyTo":"20200603015314.GA253041@google.com","subject":"Re: Huge push upload despite only having a tiny change","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-06-03T20:39:28Z","receivedAt":"2020-06-03T20:39:36Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jonathan Nieder <jrnieder@gmail.com> writes:\n\n> There is one trick a server can use to mitigate this: advertise some\n> refs that don't exist!  If you advertise a ref \".have\", then Git\n> will understand that the server has that object but it is not an\n> actual ref.  Gerrit uses this trick in its HackPushNegotiateHook[1]\n> to advertise a few recent commits.\n> ...\n> Summary: (1) try fetching first (2) let's improve\n> HackPushNegotiateHook#advertiseRefs (3) let's improve \"git push\"\n> protocol to make this a problem of the past.\n\nIn the meantime, perhaps we can teach receive-pack the same \"let's\nadvertise a few recent commits as if they exist as tips of refs\" as\nwell?\n"}]}