{"thread":{"id":"51430","subject":"Surprising use of memory and time when repacking mozilla's gecko repository","startedAt":"2019-07-04T10:05:36Z","lastAt":"2019-07-05T11:51:50Z","messageCount":11,"participants":["Mike Hommey","Eric Wong","Jeff King","Jakub Narebski"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"378594","messageId":"20190704100530.smn4rpiekwtfylhz@glandium.org","threadId":"51430","inReplyTo":null,"subject":"Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-04T10:05:30Z","receivedAt":"2019-07-04T10:05:36Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"Hi,\n\nI was looking at the disk size of the gecko repository on github[1],\nwhich started at 4.7GB, and `git gc --aggressive`'d it, which made that\ninto 2.0G. But to achieve that required quite some resources.\n\nMy first attempt failed with OOM, on an AWS instance with 16 cores and\n32GB RAM. I then went to another AWS instance, with 36 cores and 96GB\nRAM. And that went through after a while... with a peak memory usage\nabove 60GB!\n\nSince then, Peff kindly repacked the repo on the github end, so it\ndoesn't really need repacking locally anymore, but I can still reproduce\nthe > 60GB memory usage with the packed repository.\n\nI gathered some data[2], all on the same 36 cores, 96GB RAM instance, with\n36, 16 and 1 threads, and here's what can be observed:\n\nWith 36 threads, the overall process takes 45 minutes:\n- 50 seconds enumerating and counting objects.\n- ~22 minutes compressing objects\n- ~22 minutes writing objects\n\nOf the 22 minutes compressing objects, more than 15 minutes are spent on\nthe last percent of objects, and only during that part the memory usage\nballoons above 20GB.\n\nMemory usage goes back to 2.4G after finishing to compress.\n\nWith 16 threads, the overall process takes about the same time as above,\nwith about the same repartition.\n\nBut less time is spent on compressing the last percent of objects, and\nmemory usage goes above 20GB later than with 36 threads.\n\nFinally, with 1 thread, the picture changes greatly. The overall process\ntakes 2.5h:\n- 50 seconds enumerating and counting objects.\n- ~2.5h compressing objects.\n- 3 minutes and 25 seconds writing objects!\n\nMemory usage stays reasonable, except at some point after 47 minutes,\nwhere it starts to increase up to 12.7GB, and then goes back down about\nhalf an hour later, all while stalling around the 13% progress mark.\n\nMy guess is all those stalls are happening when processing the files I\nalready had problems with in the past[3], except there are more of them\nnow (thankfully, they were removed, so there won't be more, but that\ndoesn't make the existing ones go away).\n\nI never ended up working on trying to make that diff faster, maybe that\nwould help a little here, but that would probably not help much wrt the\nmemory usage. I wonder what git could reasonably do to avoid OOMing in\nthis case. Reduce the window size temporarily? Trade memory with time,\nby not keeping the objects in memory?\n\nI'm puzzled by the fact writing objects is so much faster with 1 thread.\n\nIt's worth noting that the AWS instances don't have swap by default,\nwhich is actually good in this case, because if it had started to swap,\nit would have taken forever.\n\n1. https://github.com/mozilla/gecko\n2. https://docs.google.com/spreadsheets/d/1IE8E3BhKurXsXgwBYFXs4mRBT_512v--ip6Vhxc3o-Y/edit?usp=sharing\n3. https://public-inbox.org/git/20180703223823.qedmoy2imp4dcvkp@glandium.org/T/\n\nAny thoughts?\n\nMike\n"},{"id":"378599","messageId":"20190704120411.2dlzdlsooob4dc7k@dcvr","threadId":"51430","inReplyTo":"20190704100530.smn4rpiekwtfylhz@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Eric Wong","fromEmail":"e@80x24.org","sentAt":"2019-07-04T12:04:11Z","receivedAt":"2019-07-04T12:04:13Z","isPatch":false,"sender":{"key":"e@80x24.org","avatar":null},"body":"Mike Hommey <mh@glandium.org> wrote:\n> I'm puzzled by the fact writing objects is so much faster with 1 thread.\n\nI/O contention in the multi-threaded cases?\n\n\"public-inbox-index\" (reading from git, writing to Xapian+SQLite)\non a dev machine got slow because core count exceeded what SATA\ncould handle and had to cap the default Xapian shard count to 3\nby default for v2 inboxes.\n\n\nAs for memory use, does git use the producer/consumer pattern\nfor malloc+free so free happens in a different thread from the\nmalloc?\n\nBecause current versions of glibc gets pathological with that case\n(but I have a long-term fix for it):\n\nhttps://public-inbox.org/libc-alpha/20180731084936.g4yw6wnvt677miti@dcvr/T/\nOnly locklessinc malloc seemed OK in the IPC department\n(But I haven't kept up with jemalloc, tcmalloc developments in years)\n"},{"id":"378600","messageId":"20190704131320.ksustvlayy6lby23@glandium.org","threadId":"51430","inReplyTo":"20190704120411.2dlzdlsooob4dc7k@dcvr","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-04T13:13:20Z","receivedAt":"2019-07-04T13:13:26Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"On Thu, Jul 04, 2019 at 12:04:11PM +0000, Eric Wong wrote:\n> Mike Hommey <mh@glandium.org> wrote:\n> > I'm puzzled by the fact writing objects is so much faster with 1 thread.\n> \n> I/O contention in the multi-threaded cases?\n> \n> \"public-inbox-index\" (reading from git, writing to Xapian+SQLite)\n> on a dev machine got slow because core count exceeded what SATA\n> could handle and had to cap the default Xapian shard count to 3\n> by default for v2 inboxes.\n \nAFAICT, git doesn't write from multiple threads.\n \n> As for memory use, does git use the producer/consumer pattern\n> for malloc+free so free happens in a different thread from the\n> malloc?\n> \n> Because current versions of glibc gets pathological with that case\n> (but I have a long-term fix for it):\n> \n> https://public-inbox.org/libc-alpha/20180731084936.g4yw6wnvt677miti@dcvr/T/\n> Only locklessinc malloc seemed OK in the IPC department\n> (But I haven't kept up with jemalloc, tcmalloc developments in years)\n\nOh right, I forgot to mention:\n- I thought this memory usage thing was [1] but it turns out it was real\n  memory usage.\n- glibc's mallinfo stores values as int, so it's useless to know how\n  much memory was allocated when it's more than 4GB.\n- glibc's malloc_stats relies on the same int data, so while it does\n  print \"in use\" data, it can't print values above 4GB correctly.\n- glibc has a malloc_stats function that, according to its manual page\n  \"addresses the deficiencies in malloc_stats and mallinfo\", but while\n  it outputs a large XML dump, it doesn't contain anything that looks\n  remotely like the \"in use\" from malloc_stats.\n- So all in all, I used jemalloc to gather the \"allocated\" stats.\n\nMike\n\n1. https://sourceware.org/bugzilla/show_bug.cgi?id=23416\n"},{"id":"378615","messageId":"20190705002216.logqmvrk5s354jss@glandium.org","threadId":"51430","inReplyTo":"20190704100530.smn4rpiekwtfylhz@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-05T00:22:16Z","receivedAt":"2019-07-05T00:22:21Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"On Thu, Jul 04, 2019 at 07:05:30PM +0900, Mike Hommey wrote:\n> Hi,\n> \n> I was looking at the disk size of the gecko repository on github[1],\n> which started at 4.7GB, and `git gc --aggressive`'d it, which made that\n> into 2.0G. But to achieve that required quite some resources.\n> \n> My first attempt failed with OOM, on an AWS instance with 16 cores and\n> 32GB RAM. I then went to another AWS instance, with 36 cores and 96GB\n> RAM. And that went through after a while... with a peak memory usage\n> above 60GB!\n> \n> Since then, Peff kindly repacked the repo on the github end, so it\n> doesn't really need repacking locally anymore, but I can still reproduce\n> the > 60GB memory usage with the packed repository.\n> \n> I gathered some data[2], all on the same 36 cores, 96GB RAM instance, with\n> 36, 16 and 1 threads, and here's what can be observed:\n> \n> With 36 threads, the overall process takes 45 minutes:\n> - 50 seconds enumerating and counting objects.\n> - ~22 minutes compressing objects\n> - ~22 minutes writing objects\n> \n> Of the 22 minutes compressing objects, more than 15 minutes are spent on\n> the last percent of objects, and only during that part the memory usage\n> balloons above 20GB.\n> \n> Memory usage goes back to 2.4G after finishing to compress.\n> \n> With 16 threads, the overall process takes about the same time as above,\n> with about the same repartition.\n> \n> But less time is spent on compressing the last percent of objects, and\n> memory usage goes above 20GB later than with 36 threads.\n> \n> Finally, with 1 thread, the picture changes greatly. The overall process\n> takes 2.5h:\n> - 50 seconds enumerating and counting objects.\n> - ~2.5h compressing objects.\n> - 3 minutes and 25 seconds writing objects!\n> \n> Memory usage stays reasonable, except at some point after 47 minutes,\n> where it starts to increase up to 12.7GB, and then goes back down about\n> half an hour later, all while stalling around the 13% progress mark.\n> \n> My guess is all those stalls are happening when processing the files I\n> already had problems with in the past[3], except there are more of them\n> now (thankfully, they were removed, so there won't be more, but that\n> doesn't make the existing ones go away).\n> \n> I never ended up working on trying to make that diff faster, maybe that\n> would help a little here, but that would probably not help much wrt the\n> memory usage. I wonder what git could reasonably do to avoid OOMing in\n> this case. Reduce the window size temporarily? Trade memory with time,\n> by not keeping the objects in memory?\n> \n> I'm puzzled by the fact writing objects is so much faster with 1 thread.\n\nHere's a perf report from the portion of \"Writing\" that is particularly\nslow with compression having happened on 36 threads:\n  100.00%     0.00%  git      [unknown]           [k] 0xffffffffffffffff                    \n   99.97%     0.02%  git      git                 [.] write_one                             \n   99.97%     0.00%  git      git                 [.] write_pack_file                       \n   99.97%     0.00%  git      git                 [.] cmd_pack_objects                      \n   99.96%     0.00%  git      git                 [.] write_object (inlined)                \n   99.96%     0.00%  git      git                 [.] write_reuse_object (inlined)          \n   99.92%     0.00%  git      git                 [.] write_no_reuse_object                 \n   98.12%     0.00%  git      git                 [.] get_delta (inlined)                   \n   72.36%     0.00%  git      git                 [.] diff_delta (inlined)                  \n   64.86%    64.20%  git      git                 [.] create_delta_index                    \n   26.32%     0.00%  git      git                 [.] repo_read_object_file (inlined)       \n   26.32%     0.00%  git      git                 [.] read_object_file_extended             \n   26.32%     0.00%  git      git                 [.] read_object                           \n   26.32%     0.00%  git      git                 [.] oid_object_info_extended              \n   26.25%     0.00%  git      git                 [.] packed_object_info                    \n   26.24%     0.00%  git      git                 [.] cache_or_unpack_entry (inlined)       \n   24.30%     0.01%  git      git                 [.] unpack_entry                          \n   17.62%     0.00%  git      git                 [.] memcpy (inlined)                      \n   17.52%    17.46%  git      libc-2.27.so        [.] __memmove_avx_unaligned_erms          \n   15.98%     0.22%  git      git                 [.] patch_delta                           \n    7.60%     0.00%  git      git                 [.] unpack_compressed_entry               \n    7.49%     7.42%  git      git                 [.] create_delta                          \n    7.29%     0.00%  git      git                 [.] git_inflate                           \n    7.29%     0.23%  git      libz.so.1.2.11      [.] inflate                               \n    1.94%     0.00%  git      git                 [.] xmemdupz                              \n    1.14%     0.00%  git      git                 [.] do_compress                           \n    0.98%     0.98%  git      libz.so.1.2.11      [.] adler32_z                             \n    0.95%     0.00%  git      libz.so.1.2.11      [.] deflate                               \n\n... that's a large portion of time spent on deltas...\n\nMike\n"},{"id":"378617","messageId":"20190705044530.mehpvei5lysy3czl@glandium.org","threadId":"51430","inReplyTo":"20190704100530.smn4rpiekwtfylhz@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-05T04:45:30Z","receivedAt":"2019-07-05T04:45:35Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"On Thu, Jul 04, 2019 at 07:05:30PM +0900, Mike Hommey wrote:\n> My guess is all those stalls are happening when processing the files I\n> already had problems with in the past[3], except there are more of them\n> now (thankfully, they were removed, so there won't be more, but that\n> doesn't make the existing ones go away).\n>\n> 3. https://public-inbox.org/git/20180703223823.qedmoy2imp4dcvkp@glandium.org/T/\n\nI've more or less confirmed that's the cause of the long stalls during\nthe compression phase. It can be reproduced to some extent with:\n\n$ git clone https://github.com/mozilla/gecko\n$ cd gecko\n$ git rev-list --all -- testing/web-platform/meta/MANIFEST.json | xargs -I '{}' git ls-tree '{}' testing/web-platform/meta/MANIFEST.json | sort -u | awk '{print $3}' | git cat-file --batch-check | sort -n -k 3 | awk '{print $1}' | git pack-objects --window=250 --depth=50 --no-reuse-delta my_pack\n\nThere might be some other file than testing/web-platform/meta/MANIFEST.json \ninvolved, because this uses \"only\" 40GB RAM, but that file is the one I know\nof.\n\nThis however doesn't reproduce the \"writing takes forever\" part of the\nproblem.\n\nMike\n"},{"id":"378618","messageId":"20190705050955.GA25459@sigill.intra.peff.net","threadId":"51430","inReplyTo":"20190704100530.smn4rpiekwtfylhz@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-07-05T05:09:55Z","receivedAt":"2019-07-05T05:09:59Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jul 04, 2019 at 07:05:30PM +0900, Mike Hommey wrote:\n\n> With 36 threads, the overall process takes 45 minutes:\n> - 50 seconds enumerating and counting objects.\n> - ~22 minutes compressing objects\n> - ~22 minutes writing objects\n\nI noticed the long writing phase when I repacked as well. The main cost\nthere is going to be reconstructing deltas that wouldn't fit in the\ncache. During the compression phase we generated a bunch of candidate\ndeltas. If we have space in our in-memory cache, we then store the\nactual delta there so we can write it out immediately during the writing\nphase. Otherwise, we just note the base object we used, and during the\nwriting phase we regenerate the delta on the fly.\n\nSo spending time there implies (and the perf output you posted in the\nfollowup supports this) that we have a lot of entries that could not be\ncached.\n\nYou might try poking at pack.deltaCacheSize and pack.deltaCacheLimit to\nsee if they help.\n\nBut...\n\n> Finally, with 1 thread, the picture changes greatly. The overall process\n> takes 2.5h:\n> - 50 seconds enumerating and counting objects.\n> - ~2.5h compressing objects.\n> - 3 minutes and 25 seconds writing objects!\n\nThat's weird. I'd expect us to find similar amounts of deltas, but we\ndon't have the writing slow-down. I wonder if there is some bad\ninteraction between the multi-threaded code and the delta cache.\n\nDid you run the second, single-thread run against the exact same\noriginal repository you had? Or did you re-run it on the result of the\nmulti-thread run? Another explanation is that the original repository\nhad some poor patterns that made objects expensive to access (say, a ton\nof really deep delta chains). And so the difference between the two runs\nwas not the threads, but just the on-disk repository state.\n\nKind of a long shot, but if that is what happened, try running another\nmulti-threaded \"repack -f\" and see if its writing phase is faster.\n\n> Of the 22 minutes compressing objects, more than 15 minutes are spent on\n> the last percent of objects, and only during that part the memory usage\n> balloons above 20GB.\n\nThat's not surprising. To find deltas, we make an array with all of the\nobjects, sort it into a list in a way that puts \"like\" objects near to\neach other, and then walk over that list with a sliding window, looking\nfor candidates. With multiple threads, each thread gets its own segment\nof the array to look at. So two implications are:\n\n  - one of the sorting criteria is size. So you'll often end up\n    comparing a bunch of large objects to each other at the end, and the\n    last few percent will take much more than the earlier parts.\n\n  - each thread is holding $window_size objects in memory at once. There\n    are a bunch of biggish objects, up to 17MB, in the mozilla/gecko\n    repository. So during that last part with the large objects, the\n    worst case is something like window*threads*17 = 250*36*17 = 150GB.\n\n    It's not nearly that bad because you don't have enough large\n    objects. ;) The 9000 (256*36) largest objects in that repo are only\n    55GB. And we don't hit even that at peak because some threads are\n    probably working on parts of the array with smaller objects.\n\nYou can compute that largest-9000 objects like:\n\n  git cat-file --batch-all-objects --unordered --batch-check='%(objectsize)' |\n  sort -rn | head -9000 |\n  perl -lne '$total += $_; END { print $total }'\n\nThe simplest solution if you're running into RAM problems is to turn\ndown the number of threads. You can also disable deltas for certain\nobjects (over a certain size with core.bigFileThreshold or for certain\npaths with the \"delta\" gitattribute). But in your case those big objects\nreally do make good deltas:\n\n  $ git cat-file --batch-all-objects --unordered \\\n      --batch-check='%(objectsize) %(objectsize:disk) %(deltabase)' |\n      sort -nr | head -10\n  17977953 17963093 0000000000000000000000000000000000000000\n  17817405 153050 a4ef0cf1db10163141b827863671050a58612408\n  17816806 733 529a3ffd873183abf85c78e61e50da61ccb85976\n  17816776 17939 410cc404992142e68dc53c9ecafca14adf21a839\n  17815901 571 529a3ffd873183abf85c78e61e50da61ccb85976\n  17815698 617 529a3ffd873183abf85c78e61e50da61ccb85976\n  17815668 797 d687483fbb3982bb9953ea6e67e78a5c496e9b08\n  17815668 560 10a7c4fbd756c1d961f71b7d55034011dbc0ec28\n  17815379 539 f50422a9701a018dd5c57f29d70e37c637cd8e4b\n  17815379 518 59303aa24bbbf7074ccef5dbabf0906e1c82f980\n\nSo those objects are all deltas (except the first, with all zeroes,\nwhich is the root of the base tree for all the others). And we're\ngetting lots of savings (a few hundred bytes instead of 17MB).\n\nSo I wouldn't recommend disabling deltas. Most repacks will just reuse\nthose deltas verbatim, and you won't pay any cost for them. You only do\nhere because of the aggressive, --no-delta-reuse repack.\n\n> Memory usage goes back to 2.4G after finishing to compress.\n> \n> With 16 threads, the overall process takes about the same time as above,\n> with about the same repartition.\n> \n> But less time is spent on compressing the last percent of objects, and\n> memory usage goes above 20GB later than with 36 threads.\n\nI think most of this follows from the explanations above.\n\n> Memory usage stays reasonable, except at some point after 47 minutes,\n> where it starts to increase up to 12.7GB, and then goes back down about\n> half an hour later, all while stalling around the 13% progress mark.\n\nAgain, sounds like that's where one (or more) of the threads hits that\nchunk of big objects.\n\n> My guess is all those stalls are happening when processing the files I\n> already had problems with in the past[3], except there are more of them\n> now (thankfully, they were removed, so there won't be more, but that\n> doesn't make the existing ones go away).\n\nYep, I think that's right.\n\n> I never ended up working on trying to make that diff faster, maybe that\n> would help a little here, but that would probably not help much wrt the\n> memory usage. I wonder what git could reasonably do to avoid OOMing in\n> this case. Reduce the window size temporarily? Trade memory with time,\n> by not keeping the objects in memory?\n\nThere is a config option, pack.windowMemory, which tries to do this.\nI've had mixed results experimenting with it, and never really used it\nbeyond experiments.\n\n> I'm puzzled by the fact writing objects is so much faster with 1 thread.\n\nYes, that part puzzles me too. If your answer to my earlier question is\nnegative, then it might be worth digging more into the delta-base-cache\n(perhaps starting with instrumenting it to print out which deltas did or\ndidn't get cached, along with their sizes).\n\n-Peff\n"},{"id":"378619","messageId":"20190705051412.GB25459@sigill.intra.peff.net","threadId":"51430","inReplyTo":"20190704131320.ksustvlayy6lby23@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-07-05T05:14:13Z","receivedAt":"2019-07-05T05:14:15Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jul 04, 2019 at 10:13:20PM +0900, Mike Hommey wrote:\n\n> > \"public-inbox-index\" (reading from git, writing to Xapian+SQLite)\n> > on a dev machine got slow because core count exceeded what SATA\n> > could handle and had to cap the default Xapian shard count to 3\n> > by default for v2 inboxes.\n>  \n> AFAICT, git doesn't write from multiple threads.\n\nRight. That's always single threaded, and the main difference there is\ngoing to be what's in the delta base cache.\n\n> Oh right, I forgot to mention:\n> - I thought this memory usage thing was [1] but it turns out it was real\n>   memory usage.\n> - glibc's mallinfo stores values as int, so it's useless to know how\n>   much memory was allocated when it's more than 4GB.\n> - glibc's malloc_stats relies on the same int data, so while it does\n>   print \"in use\" data, it can't print values above 4GB correctly.\n> - glibc has a malloc_stats function that, according to its manual page\n>   \"addresses the deficiencies in malloc_stats and mallinfo\", but while\n>   it outputs a large XML dump, it doesn't contain anything that looks\n>   remotely like the \"in use\" from malloc_stats.\n> - So all in all, I used jemalloc to gather the \"allocated\" stats.\n\nI think I explained all of the memory-usage questions in my earlier\nresponse, but just for reference: if you have access to it, valgrind's\n\"massif\" tool is really good for this kind of profiling. Something like:\n\n  valgrind --tool=massif git pack-objects ...\n  ms_print massif.out.*\n\nwhich shows heap usage at various times, points out the snapshot with\npeak usage, and shows a backtrace of the main culprits at a few\nsnapshots.\n\n-Peff\n"},{"id":"378620","messageId":"20190705054516.mke7aqk2cdsffkpd@glandium.org","threadId":"51430","inReplyTo":"20190705050955.GA25459@sigill.intra.peff.net","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-05T05:45:16Z","receivedAt":"2019-07-05T05:45:22Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"On Fri, Jul 05, 2019 at 01:09:55AM -0400, Jeff King wrote:\n> On Thu, Jul 04, 2019 at 07:05:30PM +0900, Mike Hommey wrote:\n> > Finally, with 1 thread, the picture changes greatly. The overall process\n> > takes 2.5h:\n> > - 50 seconds enumerating and counting objects.\n> > - ~2.5h compressing objects.\n> > - 3 minutes and 25 seconds writing objects!\n> \n> That's weird. I'd expect us to find similar amounts of deltas, but we\n> don't have the writing slow-down. I wonder if there is some bad\n> interaction between the multi-threaded code and the delta cache.\n> \n> Did you run the second, single-thread run against the exact same\n> original repository you had? Or did you re-run it on the result of the\n> multi-thread run? Another explanation is that the original repository\n> had some poor patterns that made objects expensive to access (say, a ton\n> of really deep delta chains). And so the difference between the two runs\n> was not the threads, but just the on-disk repository state.\n> \n> Kind of a long shot, but if that is what happened, try running another\n> multi-threaded \"repack -f\" and see if its writing phase is faster.\n\nI've run 36-threads, 16-threads and 1-thread in sequence on the same\nrepo, so 16-threads was repacking what was repacked by the 36-threads,\nand 1-thread was repacking what was repacked by the 16-threads. I\nassumed it didn't matter, but come to think of it, I guess it can.\n\nMike\n"},{"id":"378621","messageId":"20190705054736.6llkhnopt2fcta2k@glandium.org","threadId":"51430","inReplyTo":"20190705051412.GB25459@sigill.intra.peff.net","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-05T05:47:36Z","receivedAt":"2019-07-05T05:47:41Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"On Fri, Jul 05, 2019 at 01:14:13AM -0400, Jeff King wrote:\n> On Thu, Jul 04, 2019 at 10:13:20PM +0900, Mike Hommey wrote:\n> \n> > > \"public-inbox-index\" (reading from git, writing to Xapian+SQLite)\n> > > on a dev machine got slow because core count exceeded what SATA\n> > > could handle and had to cap the default Xapian shard count to 3\n> > > by default for v2 inboxes.\n> >  \n> > AFAICT, git doesn't write from multiple threads.\n> \n> Right. That's always single threaded, and the main difference there is\n> going to be what's in the delta base cache.\n> \n> > Oh right, I forgot to mention:\n> > - I thought this memory usage thing was [1] but it turns out it was real\n> >   memory usage.\n> > - glibc's mallinfo stores values as int, so it's useless to know how\n> >   much memory was allocated when it's more than 4GB.\n> > - glibc's malloc_stats relies on the same int data, so while it does\n> >   print \"in use\" data, it can't print values above 4GB correctly.\n> > - glibc has a malloc_stats function that, according to its manual page\n> >   \"addresses the deficiencies in malloc_stats and mallinfo\", but while\n> >   it outputs a large XML dump, it doesn't contain anything that looks\n> >   remotely like the \"in use\" from malloc_stats.\n> > - So all in all, I used jemalloc to gather the \"allocated\" stats.\n> \n> I think I explained all of the memory-usage questions in my earlier\n> response, but just for reference: if you have access to it, valgrind's\n> \"massif\" tool is really good for this kind of profiling. Something like:\n> \n>   valgrind --tool=massif git pack-objects ...\n>   ms_print massif.out.*\n> \n> which shows heap usage at various times, points out the snapshot with\n> peak usage, and shows a backtrace of the main culprits at a few\n> snapshots.\n\nAt the expense of time ;) A run would likely last an entire day under\nmassif (by which I mean a full 24 hours, not a 9-5 day).\n\nMike\n"},{"id":"378622","messageId":"86bly81zyn.fsf@gmail.com","threadId":"51430","inReplyTo":"20190705054736.6llkhnopt2fcta2k@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Jakub Narebski","fromEmail":"jnareb@gmail.com","sentAt":"2019-07-05T11:29:52Z","receivedAt":"2019-07-05T11:29:58Z","isPatch":false,"sender":{"key":"jnareb@gmail.com","avatar":"https://avatars.githubusercontent.com/u/2706?v=4"},"body":"Mike Hommey <mh@glandium.org> writes:\n\n> On Fri, Jul 05, 2019 at 01:14:13AM -0400, Jeff King wrote:\n>> On Thu, Jul 04, 2019 at 10:13:20PM +0900, Mike Hommey wrote:\n[...]\n>> I think I explained all of the memory-usage questions in my earlier\n>> response, but just for reference: if you have access to it, valgrind's\n>> \"massif\" tool is really good for this kind of profiling. Something like:\n>> \n>>   valgrind --tool=massif git pack-objects ...\n>>   ms_print massif.out.*\n>> \n>> which shows heap usage at various times, points out the snapshot with\n>> peak usage, and shows a backtrace of the main culprits at a few\n>> snapshots.\n>\n> At the expense of time ;) A run would likely last an entire day under\n> massif (by which I mean a full 24 hours, not a 9-5 day).\n\nValgrind, as I understand it, runs the program under emulation.  I\nwonder if perf / OProfile based solution could help here (gathering\nmemory-based events and metrics).\n\nThere is also trace2 built-in into Git, but I don't know if it could be\nused for this purpose or not.\n\nBest,\n--\nJakub Narębski\n"},{"id":"378624","messageId":"20190705115144.7jqvc3qzanrpvpxq@glandium.org","threadId":"51430","inReplyTo":"20190705054516.mke7aqk2cdsffkpd@glandium.org","subject":"Re: Surprising use of memory and time when repacking mozilla's gecko repository","fromName":"Mike Hommey","fromEmail":"mh@glandium.org","sentAt":"2019-07-05T11:51:44Z","receivedAt":"2019-07-05T11:51:50Z","isPatch":false,"sender":{"key":"mh@glandium.org","avatar":"https://avatars.githubusercontent.com/u/1038527?v=4"},"body":"On Fri, Jul 05, 2019 at 02:45:16PM +0900, Mike Hommey wrote:\n> On Fri, Jul 05, 2019 at 01:09:55AM -0400, Jeff King wrote:\n> > On Thu, Jul 04, 2019 at 07:05:30PM +0900, Mike Hommey wrote:\n> > > Finally, with 1 thread, the picture changes greatly. The overall process\n> > > takes 2.5h:\n> > > - 50 seconds enumerating and counting objects.\n> > > - ~2.5h compressing objects.\n> > > - 3 minutes and 25 seconds writing objects!\n> > \n> > That's weird. I'd expect us to find similar amounts of deltas, but we\n> > don't have the writing slow-down. I wonder if there is some bad\n> > interaction between the multi-threaded code and the delta cache.\n> > \n> > Did you run the second, single-thread run against the exact same\n> > original repository you had? Or did you re-run it on the result of the\n> > multi-thread run? Another explanation is that the original repository\n> > had some poor patterns that made objects expensive to access (say, a ton\n> > of really deep delta chains). And so the difference between the two runs\n> > was not the threads, but just the on-disk repository state.\n> > \n> > Kind of a long shot, but if that is what happened, try running another\n> > multi-threaded \"repack -f\" and see if its writing phase is faster.\n> \n> I've run 36-threads, 16-threads and 1-thread in sequence on the same\n> repo, so 16-threads was repacking what was repacked by the 36-threads,\n> and 1-thread was repacking what was repacked by the 16-threads. I\n> assumed it didn't matter, but come to think of it, I guess it can.\n\nI tried:\n- fresh clone -> 36-threads\n- fresh clone -> 1-thread -> 36-threads\n\nThe 36-threads gc in the latter was only marginally faster than in the\nformer (between 19 and 20 minutes instead of 22 for both \"Compressing\"\nand \"Writing\").\n\nMike\n"}]}