{"thread":{"id":"50013","subject":"High locking contention during repack?","startedAt":"2018-12-12T03:02:32Z","lastAt":"2018-12-12T21:50:40Z","messageCount":9,"participants":["Iucha, Florin","Jeff King","Ævar Arnfjörð Bjarmason"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"365149","messageId":"SN1PR12MB23840AFE62E41D908A40D1B095A70@SN1PR12MB2384.namprd12.prod.outlook.com","threadId":"50013","inReplyTo":null,"subject":"High locking contention during repack?","fromName":"Iucha, Florin","fromEmail":"florin.iucha@amd.com","sentAt":"2018-12-12T03:01:47Z","receivedAt":"2018-12-12T03:02:32Z","isPatch":false,"sender":{"key":"florin.iucha@amd.com","avatar":null},"body":"\nGreetings,\n\n \n\nI am running “git-repack -A -d -f -F --window=250 --depth=250” on a Git repository converted using git-svn.\n\n \n\nThe repository contains more than 10 years of development, and a mixture of source code and media assets. The size of the objects directory is around 50GB, and there are around 700k objects. There are several svn branches.\n\n \n\nI have ran the repack with Git 2.17.1 (original package from Ubuntu 18.04), 2.19.1 (package from Ubuntu Git PPA) and with git next (bc1bbc6f855c3b5ef7fcbd0f688f647c4e5b208b).\n\n \n\nThe system is a 16 core / 32 thread Threadripper with 128GB of RAM and NVMe storage. The repack starts strong, with 32 threads but it fairly quickly gets to 99% done and the number of threads drops to 4 then 3 then 2. However, running “dstat 5” I see lots of “sys” time without any IO time (the network traffic you see is caused by SSH).\n\n \n\n \n\n--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--\nusr sys idl wai stl| read writ| recv send| in out | int csw\n24 24 48 4 0| 0 0 | 362B 8392B| 0 0 | 64k 5042\n27 25 44 4 0| 0 0 | 289B 4830B| 0 0 | 36k 5017\n24 24 48 4 0| 0 0 | 362B 8392B| 0 0 | 64k 5042\n27 25 44 4 0| 0 0 | 289B 4830B| 0 0 | 36k 5017\n20 22 54 4 0| 0 0 | 330B 4826B| 0 0 | 31k 4657\n22 23 51 3 0| 0 0 | 286B 4834B| 0 0 | 27k 4536\n17 23 56 4 0| 0 0 | 299B 4820B| 0 0 | 29k 4099\n24 23 49 4 0| 0 0 | 347B 4830B| 0 0 | 32k 4436\n27 24 45 4 0| 0 0 | 292B 4820B| 0 0 | 22k 4513\n26 27 44 3 0| 0 0 | 292B 4820B| 0 0 | 24k 4878\n25 28 44 4 0| 0 0 | 329B 4837B| 0 0 | 45k 5023\n23 30 44 3 0| 0 9830B| 370B 4836B| 0 0 | 40k 5064\n23 26 47 4 0| 0 0 | 373B 4848B| 0 0 | 52k 4746\n25 26 45 4 0| 0 0 | 323B 4833B| 0 0 | 31k 4874\n24 28 45 3 0| 0 0 | 269B 4842B| 0 0 | 30k 4820\n25 28 43 4 0| 0 0 | 280B 4826B| 0 0 | 45k 5237\n25 29 43 3 0| 0 0 | 263B 4826B| 0 0 | 26k 5037\n22 30 45 4 0| 0 0 | 287B 4823B| 0 0 | 45k 4154\n 0 53 42 5 0| 0 0 | 275B 1210B| 0 0 |5017 1331\n 0 53 42 5 0| 0 0 | 97B 0 | 0 0 |5006 1272\n 0 53 42 5 0| 0 0 | 70B 0 | 0 0 |5008 1272\n 0 53 42 5 0| 0 0 | 24B 0 | 0 0 |5007 1283\n11 43 43 4 0| 0 0 | 644B 19k| 0 0 | 20k 2995\n25 28 43 4 0| 0 123k| 304B 4802B| 0 0 | 29k 5118\n25 27 44 4 0| 0 0 | 297B 4800B| 0 0 | 41k 5121\n26 27 43 4 0| 0 0 | 320B 4786B| 0 0 | 29k 4973\n22 30 44 3 0| 0 0 | 332B 4786B| 0 0 | 32k 4610\n24 27 46 3 0| 0 0 | 296B 4786B| 0 0 | 56k 4632\n35 17 44 3 0| 0 0 | 292B 4776B| 0 0 | 100k 4889\n34 20 43 4 0| 0 9830B| 610B 4820B| 0 0 | 59k 4811\n\n\nThis when it gets to two threads phase:\n\n 1 40 59 0 0| 0 38k| 373B 2458B| 0 0 | 50k 2874\n 0 40 59 0 0| 0 0 | 268B 2892B| 0 0 | 10k 2858\n 0 40 59 0 0| 0 0 | 299B 3102B| 0 0 |8392 2919\n 1 40 59 0 0| 0 0 | 297B 3176B| 0 0 | 21k 2831\n 0 40 59 0 0| 0 0 | 281B 3414B| 0 0 |9192 2856\n 1 40 59 0 0| 0 0 | 264B 3493B| 0 0 | 17k 2905\n 1 40 59 0 0| 0 35k| 340B 3571B| 0 0 | 13k 2885\n\n \n\nThe repack still progresses, as I see the count of repacked objects being incremented every several minutes. But I suspect there is some terrible lock contention, because otherwise I can’t explain the high system usage with no IO.\n\n \n\nRunning a strace on the running git-repack process shows only these:\n--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n\n \n\nAny idea on how to debug this? I have ran git-repack under gdb, but it seems to spin on builtin/repack.c line 409.\n \n\nThank you for Git,\n\nflorin"},{"id":"365168","messageId":"20181212112409.GB30673@sigill.intra.peff.net","threadId":"50013","inReplyTo":"SN1PR12MB23840AFE62E41D908A40D1B095A70@SN1PR12MB2384.namprd12.prod.outlook.com","subject":"Re: High locking contention during repack?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-12-12T11:24:10Z","receivedAt":"2018-12-12T11:24:13Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Dec 12, 2018 at 03:01:47AM +0000, Iucha, Florin wrote:\n\n> I am running “git-repack -A -d -f -F --window=250 --depth=250” on a\n> Git repository converted using git-svn.\n\nSort of tangential to your question, but:\n\n - Using \"-F\" implies \"-f\" already, so you don't need both. That said,\n you are probably wasting CPU to use \"-F\", unless you have adjusted\n zlib compression settings since the last pack. (Whereas using \"-f\"\n is useful, if you're willing to pay the CPU tradeoff).\n\n - Using --depth=250 does not actually decrease the packfile size very\n much, and results in a packfile which is more expensive for\n subsequent processes to use. Some experimentation showed that\n --depth=50 is a sweet spot, and that is the default for both normal\n \"git gc\" and \"git gc --aggressive\" these days.\n\n See 07e7dbf0db (gc: default aggressive depth to 50, 2016-08-11) for\n more discussion.\n\n> The system is a 16 core / 32 thread Threadripper with 128GB of RAM and\n> NVMe storage. The repack starts strong, with 32 threads but it fairly\n> quickly gets to 99% done and the number of threads drops to 4 then 3\n> then 2. However, running “dstat 5” I see lots of “sys” time without\n> any IO time (the network traffic you see is caused by SSH).\n\nThis sounds mostly normal and expected. The parallel part of a repack is\nthe delta search, which is not infinitely parallelizable. Each worker\nthread is given a \"chunk\" of objects, and it uses a sliding window to\nsearch for delta pairs through that chunk. You don't want a chunk that\napproaches the window size, since at every chunk boundary you're missing\ndelta possibilities.\n\nThe default chunk size is about 1/nr_threads of the total list size\n(i.e., we portion out all the work). And then when a thread finishes, we\ntake work from the thread with the most work remaining, and portion it\nout. However, at some point the chunks approach their minimum, and we\nstop dividing. So the number of threads will drop, eventually to 1, and\nyou'll be waiting on it to finish that final chunk.\n\nSo that's all working as planned. Having high sys load does seem a bit\nodd. Most of the effort should be going to reading the mmap'd data from\ndisk, zlib-inflating it and computing a fingerprint, and then comparing\nthe fingerprints. So that would mostly be user time.\n\n> Running a strace on the running git-repack process shows only these:\n> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n> \n> Any idea on how to debug this? I have ran git-repack under gdb, but it seems to spin on builtin/repack.c line 409.\n\nThe heavy lifting here is done by the pack-objects child process, not\ngit-repack itself. Try running with GIT_TRACE=1 in the environment to\nsee the exact invocation, but timing and debugging:\n\n git pack-objects --all --no-reuse-delta --delta-base-offset --stdout \\\n /dev/null\n\nshould produce interesting results.\n\nThe SIGALRM loop you see above is likely just the progress meter\ntriggering once per second (the actual worker threads are updating an\nint, and then at least once per second we'll show the int).\n\n-Peff\n"},{"id":"365176","messageId":"87wooen8nw.fsf@evledraar.gmail.com","threadId":"50013","inReplyTo":"20181212112409.GB30673@sigill.intra.peff.net","subject":"Re: High locking contention during repack?","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-12-12T14:04:19Z","receivedAt":"2018-12-12T14:04:27Z","isPatch":false,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Wed, Dec 12 2018, Jeff King wrote:\n\n> On Wed, Dec 12, 2018 at 03:01:47AM +0000, Iucha, Florin wrote:\n>\n>> I am running “git-repack -A -d -f -F --window=250 --depth=250” on a\n>> Git repository converted using git-svn.\n>\n> Sort of tangential to your question, but:\n>\n> - Using \"-F\" implies \"-f\" already, so you don't need both. That said,\n> you are probably wasting CPU to use \"-F\", unless you have adjusted\n> zlib compression settings since the last pack. (Whereas using \"-f\"\n> is useful, if you're willing to pay the CPU tradeoff).\n>\n> - Using --depth=250 does not actually decrease the packfile size very\n> much, and results in a packfile which is more expensive for\n> subsequent processes to use. Some experimentation showed that\n> --depth=50 is a sweet spot, and that is the default for both normal\n> \"git gc\" and \"git gc --aggressive\" these days.\n>\n> See 07e7dbf0db (gc: default aggressive depth to 50, 2016-08-11) for\n> more discussion.\n\nI wonder if the size is still too high. I'd rather take the 5-10%\nspeedup quoted in that commit than a slight decrease in disk space use.\n\nThe git.git repository now with the repack command in that commit\nmessage, with --depth=$n:\n\n 573M /tmp/git-1\n 200M /tmp/git-2\n 118M /tmp/git-3\n 91M /tmp/git-4\n 82M /tmp/git-5\n 77M /tmp/git-6\n 74M /tmp/git-7\n 72M /tmp/git-8\n 71M /tmp/git-9\n 70M /tmp/git-10\n 67M /tmp/git-15\n 66M /tmp/git-20\n 65M /tmp/git-40\n 65M /tmp/git-35\n 65M /tmp/git-30\n 65M /tmp/git-25\n 64M /tmp/git-50\n 64M /tmp/git-45\n\nProduced via:\n\n parallel 'rm -rf /tmp/git-{}; cp -Rvp /tmp/git.git/ /tmp/git-{} && git -C /tmp/git-{} repack -adf --depth={} --window=250' ::: {1..10} 15 20 25 30 35 40 45 50\n\nAnd then the log -S benchmarks:\n\n s/iter log -S 1 log -S 50 log -S 45 log -S 35 log -S 30 log -S 25 log -S 20 log -S 15 log -S 10 log -S 5\n log -S 1 12.6 -- -26% -27% -32% -36% -38% -38% -39% -40% -42%\n log -S 50 9.28 36% -- -0% -7% -13% -15% -16% -18% -19% -21%\n log -S 45 9.25 36% 0% -- -7% -12% -15% -16% -17% -19% -20%\n log -S 35 8.62 46% 8% 7% -- -6% -9% -10% -11% -13% -14%\n log -S 30 8.12 55% 14% 14% 6% -- -3% -4% -6% -8% -9%\n log -S 25 7.86 60% 18% 18% 10% 3% -- -1% -3% -5% -6%\n log -S 20 7.77 62% 19% 19% 11% 4% 1% -- -2% -3% -5%\n log -S 15 7.64 65% 21% 21% 13% 6% 3% 2% -- -2% -4%\n log -S 10 7.51 68% 24% 23% 15% 8% 5% 3% 2% -- -2%\n log -S 5 7.37 71% 26% 25% 17% 10% 7% 5% 4% 2% --\n\nSo we're getting a 20% speedup in log -S by using --depth=5 instead of\n--depth=50, neatly at the cost of 20% more disk space, but could also\nget a 19% speedup for 8% (--depth=10) more disk space, etc.\n\nThen in rev-list it makes less of a difference, narrowing this down a\nbit:\n\n s/iter rev-list 50 rev-list 25 rev-list 10 rev-list 5\n rev-list 50 1.61 -- -1% -4% -5%\n rev-list 25 1.60 1% -- -3% -4%\n rev-list 10 1.55 4% 3% -- -1%\n rev-list 5 1.54 5% 4% 1% --\n\nIt seems to me we should at least move this to --depth=25 by default. A\n~15% speedup in log -S & other mass-blob lookups for 1.5% more disk\nspace seems like a good trade-off. As your commit notes RAM (or disk\nspace) is not commonly the bottleneck anymore.\n\n>> The system is a 16 core / 32 thread Threadripper with 128GB of RAM and\n>> NVMe storage. The repack starts strong, with 32 threads but it fairly\n>> quickly gets to 99% done and the number of threads drops to 4 then 3\n>> then 2. However, running “dstat 5” I see lots of “sys” time without\n>> any IO time (the network traffic you see is caused by SSH).\n>\n> This sounds mostly normal and expected. The parallel part of a repack is\n> the delta search, which is not infinitely parallelizable. Each worker\n> thread is given a \"chunk\" of objects, and it uses a sliding window to\n> search for delta pairs through that chunk. You don't want a chunk that\n> approaches the window size, since at every chunk boundary you're missing\n> delta possibilities.\n>\n> The default chunk size is about 1/nr_threads of the total list size\n> (i.e., we portion out all the work). And then when a thread finishes, we\n> take work from the thread with the most work remaining, and portion it\n> out. However, at some point the chunks approach their minimum, and we\n> stop dividing. So the number of threads will drop, eventually to 1, and\n> you'll be waiting on it to finish that final chunk.\n>\n> So that's all working as planned. Having high sys load does seem a bit\n> odd. Most of the effort should be going to reading the mmap'd data from\n> disk, zlib-inflating it and computing a fingerprint, and then comparing\n> the fingerprints. So that would mostly be user time.\n>\n>> Running a strace on the running git-repack process shows only these:\n>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---\n>>\n>> Any idea on how to debug this? I have ran git-repack under gdb, but it seems to spin on builtin/repack.c line 409.\n>\n> The heavy lifting here is done by the pack-objects child process, not\n> git-repack itself. Try running with GIT_TRACE=1 in the environment to\n> see the exact invocation, but timing and debugging:\n>\n> git pack-objects --all --no-reuse-delta --delta-base-offset --stdout \\\n> /dev/null\n>\n> should produce interesting results.\n>\n> The SIGALRM loop you see above is likely just the progress meter\n> triggering once per second (the actual worker threads are updating an\n> int, and then at least once per second we'll show the int).\n>\n> -Peff\n"},{"id":"365180","messageId":"SN1PR12MB23849A5B991FB7D9213FB64595A70@SN1PR12MB2384.namprd12.prod.outlook.com","threadId":"50013","inReplyTo":"20181212112409.GB30673@sigill.intra.peff.net","subject":"RE: High locking contention during repack?","fromName":"Iucha, Florin","fromEmail":"florin.iucha@amd.com","sentAt":"2018-12-12T16:49:37Z","receivedAt":"2018-12-12T16:49:41Z","isPatch":false,"sender":{"key":"florin.iucha@amd.com","avatar":null},"body":"Jeff,\n\nThank you for the advice, I will reduce the depth.\n\nRunning \"git pack-objects --all --no-reuse-delta --delta-base-offset --stdout /dev/null\", it got to 99% fairly quickly, now it has 5 threads running (using 99.9% CPU), but the \"dstat 5\" still shows lots of nothing, with some heavy system activity:\n\n--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--\nusr sys idl wai stl| read writ| recv send| in out | int csw \n 1 8 91 0 0| 166k 224k| 0 0 | 0 0 |6892 970 \n 0 13 87 0 0| 0 0 | 333B 1758B| 0 0 |2285 1374 \n 0 13 87 0 0| 0 0 | 309B 1190B| 0 0 |2233 1265 \n 0 13 87 0 0| 0 0 | 282B 1053B| 0 0 |2174 1239 \n 0 13 87 0 0| 0 0 | 278B 1251B| 0 0 |1930 1173 \n 0 13 87 0 0| 0 0 | 274B 942B| 0 0 |1987 1139 \n 0 13 87 0 0| 0 0 | 264B 1168B| 0 0 |1928 1205 \n 0 13 87 0 0| 0 0 | 388B 2435B| 0 0 |2245 1280 \n 0 13 87 0 0| 0 0 | 268B 1145B| 0 0 |2225 1221 \n 0 13 87 0 0| 0 0 | 164B 732B| 0 0 |2607 1333 \n 0 13 87 0 0| 0 0 | 156B 996B| 0 0 |2100 1270 \n 0 13 87 0 0| 0 0 | 206B 1019B| 0 0 |2192 1296 \n 0 13 87 0 0| 0 0 | 198B 824B| 0 0 |2019 1236 \n 0 13 87 0 0| 0 0 | 245B 435B| 0 0 |1974 1195 \n 0 13 87 0 0| 0 0 | 252B 855B| 0 0 |1852 1166 \n 0 13 87 0 0| 0 0 | 230B 758B| 0 0 |2066 1299 \n 0 13 87 0 0| 0 0 | 284B 925B| 0 0 |1860 1225 \n 0 13 87 0 0| 0 0 | 289B 2682B| 0 0 |1796 1197 \n 0 13 87 0 0| 0 0 | 939B 1263B| 0 0 |1913 1304 \n 0 13 87 0 0| 0 0 |1212B 1366B| 0 0 |1915 1343\n\nI will try running the command under the debugger and stop it when it gets to this point and poke around.\n\nflorin\n"},{"id":"365181","messageId":"CACBZZX6YsWs7Q3g3UARgBLQZniZUuPPuM2kaw-PHmtO+ZZrnkQ@mail.gmail.com","threadId":"50013","inReplyTo":"SN1PR12MB23849A5B991FB7D9213FB64595A70@SN1PR12MB2384.namprd12.prod.outlook.com","subject":"Re: High locking contention during repack?","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-12-12T16:54:07Z","receivedAt":"2018-12-12T16:54:21Z","isPatch":false,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"On Wed, Dec 12, 2018 at 5:52 PM Iucha, Florin wrote:\n>\n> Jeff,\n>\n> Thank you for the advice, I will reduce the depth.\n>\n> Running \"git pack-objects --all --no-reuse-delta --delta-base-offset --stdout /dev/null\", it got to 99% fairly quickly, now it has 5 threads running (using 99.9% CPU), but the \"dstat 5\" still shows lots of nothing, with some heavy system activity:\n>\n> --total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--\n> usr sys idl wai stl| read writ| recv send| in out | int csw\n> 1 8 91 0 0| 166k 224k| 0 0 | 0 0 |6892 970\n> 0 13 87 0 0| 0 0 | 333B 1758B| 0 0 |2285 1374\n> 0 13 87 0 0| 0 0 | 309B 1190B| 0 0 |2233 1265\n> 0 13 87 0 0| 0 0 | 282B 1053B| 0 0 |2174 1239\n> 0 13 87 0 0| 0 0 | 278B 1251B| 0 0 |1930 1173\n> 0 13 87 0 0| 0 0 | 274B 942B| 0 0 |1987 1139\n> 0 13 87 0 0| 0 0 | 264B 1168B| 0 0 |1928 1205\n> 0 13 87 0 0| 0 0 | 388B 2435B| 0 0 |2245 1280\n> 0 13 87 0 0| 0 0 | 268B 1145B| 0 0 |2225 1221\n> 0 13 87 0 0| 0 0 | 164B 732B| 0 0 |2607 1333\n> 0 13 87 0 0| 0 0 | 156B 996B| 0 0 |2100 1270\n> 0 13 87 0 0| 0 0 | 206B 1019B| 0 0 |2192 1296\n> 0 13 87 0 0| 0 0 | 198B 824B| 0 0 |2019 1236\n> 0 13 87 0 0| 0 0 | 245B 435B| 0 0 |1974 1195\n> 0 13 87 0 0| 0 0 | 252B 855B| 0 0 |1852 1166\n> 0 13 87 0 0| 0 0 | 230B 758B| 0 0 |2066 1299\n> 0 13 87 0 0| 0 0 | 284B 925B| 0 0 |1860 1225\n> 0 13 87 0 0| 0 0 | 289B 2682B| 0 0 |1796 1197\n> 0 13 87 0 0| 0 0 | 939B 1263B| 0 0 |1913 1304\n> 0 13 87 0 0| 0 0 |1212B 1366B| 0 0 |1915 1343\n>\n> I will try running the command under the debugger and stop it when it gets to this point and poke around.\n\nFWIW compiling with gcc's gprof support is probably a better way to\nfigure out \"what was my program doing all this time?\".\n"},{"id":"365184","messageId":"SN1PR12MB2384362EE5BA4980322931B795A70@SN1PR12MB2384.namprd12.prod.outlook.com","threadId":"50013","inReplyTo":"SN1PR12MB23849A5B991FB7D9213FB64595A70@SN1PR12MB2384.namprd12.prod.outlook.com","subject":"RE: High locking contention during repack?","fromName":"Iucha, Florin","fromEmail":"florin.iucha@amd.com","sentAt":"2018-12-12T18:08:12Z","receivedAt":"2018-12-12T18:08:17Z","isPatch":false,"sender":{"key":"florin.iucha@amd.com","avatar":null},"body":"(Apologize for top-posting but making Outlook quote properly is a bear)\n\nDown to 1+4 threads:\n\n--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--\nusr sys idl wai stl| read writ| recv send| in out | int csw \n 0 13 87 0 0| 0 0 |2059B 15k| 0 0 |2200 1730 \n 0 13 87 0 0| 0 0 | 585B 2754B| 0 0 |1792 1269 \n 0 13 87 0 0| 0 0 | 178B 734B| 0 0 |1691 1157 \n 0 13 87 0 0| 0 6554B| 225B 734B| 0 0 |1885 1238 \n 0 13 87 0 0| 0 0 | 159B 736B| 0 0 |1958 1262 \n 0 13 87 0 0| 0 0 | 310B 760B| 0 0 |1813 1175\n\n(gdb) info threads\n Id Target Id Frame \n* 1 Thread 0x7f7b837dcb80 (LWP 11918) \"git\" 0x000055c7dded56eb in ll_find_deltas (processed=0x7ffce7da82a8, depth=, window=, \n list_size=0, list=) at builtin/pack-objects.c:2516\n 2 Thread 0x7f782e16a700 (LWP 11929) \"git\" create_delta (index=0x55c807d2ff20, trg_buf=, trg_size=trg_size@entry=9677636, \n delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674) at diff-delta.c:381\n 3 Thread 0x7f6fe77fe700 (LWP 11948) \"git\" create_delta (index=0x7f6e35171010, trg_buf=, trg_size=trg_size@entry=163385853, \n delta_size=delta_size@entry=0x7f6fe77fde78, max_size=2328926) at diff-delta.c:381\n 4 Thread 0x7f6fe67fc700 (LWP 11950) \"git\" create_delta (index=0x7f6e3f7f3010, trg_buf=, trg_size=trg_size@entry=74543780, \n delta_size=delta_size@entry=0x7f6fe67fbe78, max_size=2582505) at diff-delta.c:381\n 5 Thread 0x7f6fe5ffb700 (LWP 11951) \"git\" create_delta (index=0x7f6f01d06010, trg_buf=, trg_size=trg_size@entry=28510185, \n delta_size=delta_size@entry=0x7f6fe5ffae78, max_size=9146484) at diff-delta.c:381\n(gdb) bt\n#0 0x00007f7b82f909f3 in futex_wait_cancelable (private=, expected=0, futex_word=0x55c7de2ff348 )\n at ../sysdeps/unix/sysv/linux/futex-internal.h:88\n#1 __pthread_cond_wait_common (abstime=0x0, mutex=0x55c7de2ff360 , cond=0x55c7de2ff320 ) at pthread_cond_wait.c:502\n#2 __pthread_cond_wait (cond=cond@entry=0x55c7de2ff320 , mutex=mutex@entry=0x55c7de2ff360 ) at pthread_cond_wait.c:655\n#3 0x000055c7dded56eb in ll_find_deltas (processed=0x7ffce7da82a8, depth=, window=, list_size=0, list=)\n at builtin/pack-objects.c:2516\n#4 prepare_pack (depth=, window=) at builtin/pack-objects.c:2673\n#5 cmd_pack_objects (argc=, argv=, prefix=) at builtin/pack-objects.c:3491\n#6 0x000055c7dde74711 in run_builtin (argv=, argc=, p=) at git.c:421\n#7 handle_builtin (argc=, argv=) at git.c:647\n#8 0x000055c7dde75725 in run_argv (argv=0x7ffce7daa7e0, argcp=0x7ffce7daa7ec) at git.c:701\n#9 cmd_main (argc=, argv=) at git.c:798\n#10 0x000055c7dde7437f in main (argc=6, argv=0x7ffce7daaa58) at common-main.c:45\n(gdb) thread 2\n[Switching to thread 2 (Thread 0x7f782e16a700 (LWP 11929))]\n#0 create_delta (index=0x55c807d2ff20, trg_buf=, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)\n at diff-delta.c:381\n381 if (entry->val != val)\n(gdb) bt\n#0 create_delta (index=0x55c807d2ff20, trg_buf=, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)\n at diff-delta.c:381\n#1 0x000055c7dded0606 in try_delta (mem_usage=, max_depth=50, src=0x7f702c256bc0, trg=0x7f702c256ca0) at builtin/pack-objects.c:2129\n#2 find_deltas (list=, list_size=list_size@entry=0x55c7e467daf4, window=, depth=, processed=)\n at builtin/pack-objects.c:2262\n#3 0x000055c7dded0e29 in threaded_find_deltas (arg=0x55c7e467dae0) at builtin/pack-objects.c:2408\n#4 0x00007f7b82f8a6db in start_thread (arg=0x7f782e16a700) at pthread_create.c:463\n#5 0x00007f7b82cb388f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95\n(gdb) thread 2\n[Switching to thread 2 (Thread 0x7f782e16a700 (LWP 11929))]\n#0 create_delta (index=0x55c807d2ff20, trg_buf=, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)\n at diff-delta.c:381\n381 if (entry->val != val)\n(gdb) bt\n#0 create_delta (index=0x55c807d2ff20, trg_buf=, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)\n at diff-delta.c:381\n#1 0x000055c7dded0606 in try_delta (mem_usage=, max_depth=50, src=0x7f702c256bc0, trg=0x7f702c256ca0) at builtin/pack-objects.c:2129\n#2 find_deltas (list=, list_size=list_size@entry=0x55c7e467daf4, window=, depth=, processed=)\n at builtin/pack-objects.c:2262\n#3 0x000055c7dded0e29 in threaded_find_deltas (arg=0x55c7e467dae0) at builtin/pack-objects.c:2408\n#4 0x00007f7b82f8a6db in start_thread (arg=0x7f782e16a700) at pthread_create.c:463\n#5 0x00007f7b82cb388f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95\n\nflorin\n\n-----Original Message-----\nFrom: Iucha, Florin \nSent: Wednesday, December 12, 2018 11:50 AM\nTo: 'Jeff King' \nCc: git@vger.kernel.org\nSubject: RE: High locking contention during repack?\n\nJeff,\n\nThank you for the advice, I will reduce the depth.\n\nRunning \"git pack-objects --all --no-reuse-delta --delta-base-offset --stdout /dev/null\", it got to 99% fairly quickly, now it has 5 threads running (using 99.9% CPU), but the \"dstat 5\" still shows lots of nothing, with some heavy system activity:\n\n--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--\nusr sys idl wai stl| read writ| recv send| in out | int csw \n 1 8 91 0 0| 166k 224k| 0 0 | 0 0 |6892 970 \n 0 13 87 0 0| 0 0 | 333B 1758B| 0 0 |2285 1374 \n 0 13 87 0 0| 0 0 | 309B 1190B| 0 0 |2233 1265 \n 0 13 87 0 0| 0 0 | 282B 1053B| 0 0 |2174 1239 \n 0 13 87 0 0| 0 0 | 278B 1251B| 0 0 |1930 1173 \n 0 13 87 0 0| 0 0 | 274B 942B| 0 0 |1987 1139 \n 0 13 87 0 0| 0 0 | 264B 1168B| 0 0 |1928 1205 \n 0 13 87 0 0| 0 0 | 388B 2435B| 0 0 |2245 1280 \n 0 13 87 0 0| 0 0 | 268B 1145B| 0 0 |2225 1221 \n 0 13 87 0 0| 0 0 | 164B 732B| 0 0 |2607 1333 \n 0 13 87 0 0| 0 0 | 156B 996B| 0 0 |2100 1270 \n 0 13 87 0 0| 0 0 | 206B 1019B| 0 0 |2192 1296 \n 0 13 87 0 0| 0 0 | 198B 824B| 0 0 |2019 1236 \n 0 13 87 0 0| 0 0 | 245B 435B| 0 0 |1974 1195 \n 0 13 87 0 0| 0 0 | 252B 855B| 0 0 |1852 1166 \n 0 13 87 0 0| 0 0 | 230B 758B| 0 0 |2066 1299 \n 0 13 87 0 0| 0 0 | 284B 925B| 0 0 |1860 1225 \n 0 13 87 0 0| 0 0 | 289B 2682B| 0 0 |1796 1197 \n 0 13 87 0 0| 0 0 | 939B 1263B| 0 0 |1913 1304 \n 0 13 87 0 0| 0 0 |1212B 1366B| 0 0 |1915 1343\n\nI will try running the command under the debugger and stop it when it gets to this point and poke around.\n\nflorin\n"},{"id":"365188","messageId":"SN1PR12MB2384587486B6D10F2784CEB795A70@SN1PR12MB2384.namprd12.prod.outlook.com","threadId":"50013","inReplyTo":"SN1PR12MB2384362EE5BA4980322931B795A70@SN1PR12MB2384.namprd12.prod.outlook.com","subject":"RE: High locking contention during repack?","fromName":"Iucha, Florin","fromEmail":"florin.iucha@amd.com","sentAt":"2018-12-12T18:30:47Z","receivedAt":"2018-12-12T18:30:51Z","isPatch":false,"sender":{"key":"florin.iucha@amd.com","avatar":null},"body":"It seems to be spending a lot of time in create_delta. I have added a breakpoint on calling create_delta and a few good minutes pass between the breakpoint being hit. The large loop in create_delta has practically no outgoing function calls (save for the realloc on line 476), so I still don't understand how dstat could report 0% user time. htop indicates the worker threads are using 100% CPU time.\n\nflorin\n"},{"id":"365191","messageId":"SN1PR12MB23844F35A879EA185AD6B00B95A70@SN1PR12MB2384.namprd12.prod.outlook.com","threadId":"50013","inReplyTo":"SN1PR12MB2384587486B6D10F2784CEB795A70@SN1PR12MB2384.namprd12.prod.outlook.com","subject":"RE: High locking contention during repack?","fromName":"Iucha, Florin","fromEmail":"florin.iucha@amd.com","sentAt":"2018-12-12T19:05:38Z","receivedAt":"2018-12-12T19:05:44Z","isPatch":false,"sender":{"key":"florin.iucha@amd.com","avatar":null},"body":"Is there an easy way to figure out what object we're processing in create_delta? I have filtered out some large data files in .gitattributes already.\n\nflorin\n"},{"id":"365205","messageId":"SN1PR12MB2384DADBA94F3F9435E5E9D895A70@SN1PR12MB2384.namprd12.prod.outlook.com","threadId":"50013","inReplyTo":"SN1PR12MB23844F35A879EA185AD6B00B95A70@SN1PR12MB2384.namprd12.prod.outlook.com","subject":"RE: High locking contention during repack?","fromName":"Iucha, Florin","fromEmail":"florin.iucha@amd.com","sentAt":"2018-12-12T21:50:36Z","receivedAt":"2018-12-12T21:50:40Z","isPatch":false,"sender":{"key":"florin.iucha@amd.com","avatar":null},"body":"> Is there an easy way to figure out what object we're processing in create_delta? I have filtered out some large data files in .gitattributes already.\n\nFor the record:\n* add breakpoint on create_delta at diff-delta.c:321\n* stop the execution\n* switch to the worker thread\n* select frame 3: threaded_find_deltas at builtin/pack-objects.c:2408\n* p/x me->list.idx.oid.hash\n\nflorin\n"}]}