{"thread":{"id":"56013","subject":"[GSoC] Git Blog 6","startedAt":"2021-06-27T12:44:01Z","lastAt":"2021-06-28T15:55:59Z","messageCount":3,"participants":["ZheNing Hu","Christian Couder"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"428569","messageId":"CAOLTT8TLhL3MNnkB7s1J4hAQmovaUPoeydn8kepzFOT_UL83_Q@mail.gmail.com","threadId":"56013","inReplyTo":null,"subject":"[GSoC] Git Blog 6","fromName":"ZheNing Hu","fromEmail":"adlternative@gmail.com","sentAt":"2021-06-27T12:43:45Z","receivedAt":"2021-06-27T12:44:01Z","isPatch":false,"sender":{"key":"adlternative@gmail.com","avatar":"https://avatars.githubusercontent.com/u/58138461?v=4"},"body":"My sixth week blog finished:\nThe web version is here:\nhttps://adlternative.github.io/GSOC-Git-Blog-6/\n\n## Week6: Performance Testing\n\nThis week, `Christan`, `Hariom`, and `Bagas` reviewed my patches. I\nrevised the commit\nmessages and made some content adjustments based on their suggestions.\nPatch is here:\n [[PATCH v6 00/15] [GSOC][RFC] cat-file: reuse ref-filter\nlogic](https://lore.kernel.org/git/pull.980.v6.git.1624797350.gitgitgadget@gmail.com/).\n\nCompared with the big changes that made `git cat-file` re-use\n`ref-filter` logic in previous\nweeks, the overall change this week is not very large.\n\nAlthough from a functional point of view, the current version of `git\ncat-file` can support more\natoms, but from a performance point of view, it is far less than the\nprevious version.\n\nThe following is an excerpt from the commit message of `[GSOC]\ncat-file: reuse ref-filter logic`:\n\n```\nThe performance for `git cat-file --batch-all-objects\n--batch-check` on the Git repository itself with performance\ntesting tool `hyperfine` changes from 669.4 ms ± 31.1 ms to\n1.134 s ± 0.063 s.\n\nThe performance for `git cat-file --batch-all-objects --batch\n>/dev/null` on the Git repository itself with performance testing\ntool `time` change from \"27.37s user 0.29s system 98% cpu 28.089\ntotal\" to \"33.69s user 1.54s system 87% cpu 40.258 total\".\n```\n\nNow the performance of `cat-file --batch` is almost half of the\nprevious performance of it,\nbecause of the complex logic in `ref-filter`. So I am thinking, how\ncan I find the performance\nbottleneck in `ref-filter` and optimize it?\n\nSo I try to find and use performance testing tools to analyze the\ntime-consuming steps of\n`git cat-file --batch`.\n\n* Using Google's `gperftools`:\n1. Add the link parameter `-lprofiler` in `config.mak`: `CFLAGS += -lprofiler`.\n2. `make`.\n3. Use `CPUPROFILE=/tmp/prof.out /<path>/git cat-file --batch-check\n--batch-all-objects`\nto run the git and general `prof.out`, which contains the results of\nperformance analysis.\n4. Use `pprof --text /<path>/git /tmp/prof.out` to display the result\nin the terminal.\n\n* `git cat-file` after re-using the `ref-filter` logic:\n\n```\nUsing local file /<path>/git.\nUsing local file /<path>/prof.out.\n/usr/bin/addr2line: /<path>/git: file format not recognized\nTotal: 283 samples\n62 21.9% 21.9% 62 21.9% __GI___libc_write\n34 12.0% 33.9% 34 12.0% 000055d9164cdc36\n20 7.1% 41.0% 20 7.1% inflate\n12 4.2% 45.2% 12 4.2% inflateCodesUsed@@ZLIB_1.2.9\n8 2.8% 48.1% 8 2.8% __memcmp_avx2_movbe\n7 2.5% 50.5% 7 2.5% 000055d9164cdc33\n5 1.8% 52.3% 5 1.8% __libc_open64\n5 1.8% 54.1% 5 1.8% __memmove_avx_unaligned_erms\n5 1.8% 55.8% 5 1.8% _int_malloc\n3 1.1% 56.9% 3 1.1% 000055d9164ccbce\n3 1.1% 58.0% 3 1.1% malloc_consolidate\n2 0.7% 58.7% 2 0.7% 000055d916478d78\n2 0.7% 59.4% 2 0.7% 000055d9164cc821\n2 0.7% 60.1% 2 0.7% 000055d9164cc8f5\n2 0.7% 60.8% 2 0.7% 000055d9164ccc49\n2 0.7% 61.5% 2 0.7% 000055d91659dc02\n2 0.7% 62.2% 2 0.7% __GI___libc_free\n2 0.7% 62.9% 2 0.7% __calloc\n2 0.7% 63.6% 2 0.7% __fstatat64\n2 0.7% 64.3% 2 0.7% __memset_avx2_unaligned_erms\n2 0.7% 65.0% 2 0.7% __strlen_avx2\n2 0.7% 65.7% 2 0.7% __vfprintf_internal\n...\n1 0.4% 92.9% 1 0.4% _IO_new_do_write\n1 0.4% 93.3% 1 0.4% _IO_new_file_write\n1 0.4% 93.6% 1 0.4% _IO_old_init\n1 0.4% 94.0% 1 0.4% _IO_str_init_static_internal\n1 0.4% 94.3% 1 0.4% __GI__IO_default_xsputn\n1 0.4% 94.7% 1 0.4% __GI__IO_fwrite\n1 0.4% 95.1% 1 0.4% __GI__IO_setb\n1 0.4% 95.4% 1 0.4% __GI___libc_malloc\n1 0.4% 95.8% 1 0.4% __GI___mmap64\n1 0.4% 96.1% 1 0.4% __GI___qsort_r\n1 0.4% 96.5% 1 0.4% __GI_munmap\n1 0.4% 96.8% 1 0.4% __abi_tag\n1 0.4% 97.2% 1 0.4% __strchr_avx2\n1 0.4% 97.5% 1 0.4% _int_free\n1 0.4% 97.9% 1 0.4% _itoa_word\n1 0.4% 98.2% 1 0.4% adler32_z@@ZLIB_1.2.9\n1 0.4% 98.6% 1 0.4% inflateBackEnd@@ZLIB_1.2.0\n1 0.4% 98.9% 1 0.4% inflateReset2@@ZLIB_1.2.3.4\n1 0.4% 99.3% 4 1.4% msort_with_tmp.part.0\n1 0.4% 99.6% 1 0.4% unlink_chunk.constprop.0\n1 0.4% 100.0% 1 0.4% zError\n...\n0 0.0% 100.0% 150 53.0% __libc_start_main\n```\n\n* `git cat-file` before re-using the `ref-filter` logic:\n\n```\nUsing local file /<path>/git.\nUsing local file /tmp/prof.out2.\n/usr/bin/addr2line: /<path>/git: file format not recognized\nTotal: 234 samples\n52 22.2% 22.2% 52 22.2% __GI___libc_write\n24 10.3% 32.5% 24 10.3% 00005564fbe6b0da\n23 9.8% 42.3% 23 9.8% inflateCodesUsed@@ZLIB_1.2.9\n11 4.7% 47.0% 11 4.7% inflate\n9 3.8% 50.9% 9 3.8% 00005564fbe6b0d7\n7 3.0% 53.8% 7 3.0% __memcmp_avx2_movbe\n5 2.1% 56.0% 5 2.1% _int_malloc\n4 1.7% 57.7% 4 1.7% __libc_open64\n3 1.3% 59.0% 3 1.3% __GI__IO_default_xsputn\n3 1.3% 60.3% 3 1.3% __memmove_avx_unaligned_erms\n3 1.3% 61.5% 3 1.3% __strchrnul_avx2\n2 0.9% 62.4% 2 0.9% 00005564fbe1621c\n2 0.9% 63.2% 2 0.9% 00005564fbe6813a\n2 0.9% 64.1% 2 0.9% 00005564fbe6b0dd\n2 0.9% 65.0% 2 0.9% 00005564fbe6b0e9\n2 0.9% 65.8% 2 0.9% 00005564fbe6b8f6\n2 0.9% 66.7% 2 0.9% 00005564fbef4ce6\n2 0.9% 67.5% 2 0.9% __GI___libc_malloc\n...\n1 0.4% 97.4% 1 0.4% _IO_new_file_write\n1 0.4% 97.9% 1 0.4% _IO_new_file_xsputn\n1 0.4% 98.3% 1 0.4% __GI___libc_free\n1 0.4% 98.7% 1 0.4% __strlen_avx2\n1 0.4% 99.1% 1 0.4% __vsnprintf_internal\n1 0.4% 99.6% 1 0.4% adler32_z@@ZLIB_1.2.9\n1 0.4% 100.0% 1 0.4% inflateBackEnd@@ZLIB_1.2.0\n...\n0 0.0% 100.0% 118 50.4% __libc_start_main\n0 0.0% 100.0% 4 1.7% msort_with_tmp.part.0\n```\n\nIgnore `write`, `inflate` and `000055d9164cdc36`, the execution time of `memcmp`\nand `memmove` is very large.\n\nHowever, whether it is `git cat-file` before or after re-using the\n`ref-filter` logic,\nthe functions they call take up similar proportions of time.\n* Using `perf`:\n`perf top -p <git-pid>`\n\n```\n12.72% libc-2.33.so [.] __memmove_avx_unaligned_erms\n7.39% libz.so.1.2.11 [.] inflate\n5.56% libz.so.1.2.11 [.] 0x00000000000088ba\n5.27% libz.so.1.2.11 [.] adler32_z\n3.46% git [.] patch_delta\n```\nWe can see that `memmove` is still the part that accounts for the\nlargest proportion of time.\n\nWe can already come to a conclusion: A lot of the time of `cat-file\n--batch` is used for data copy,\nthis may be the focus of our later performance optimization.\n\n--\nZheNing Hu\n"},{"id":"428577","messageId":"CAP8UFD0dDeL6crqqXPRd+564Z8n_EX3ctzRxKyGZFBp2SjbXEQ@mail.gmail.com","threadId":"56013","inReplyTo":"CAOLTT8TLhL3MNnkB7s1J4hAQmovaUPoeydn8kepzFOT_UL83_Q@mail.gmail.com","subject":"Re: [GSoC] Git Blog 6","fromName":"Christian Couder","fromEmail":"christian.couder@gmail.com","sentAt":"2021-06-27T21:52:59Z","receivedAt":"2021-06-27T21:53:15Z","isPatch":false,"sender":{"key":"christian.couder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/208954?v=4"},"body":"On Sun, Jun 27, 2021 at 2:43 PM ZheNing Hu <adlternative@gmail.com> wrote:\n>\n> My sixth week blog finished:\n> The web version is here:\n> https://adlternative.github.io/GSOC-Git-Blog-6/\n\nGreat!\n\n[...]\n\n> Now the performance of `cat-file --batch` is almost half of the\n> previous performance of it,\n> because of the complex logic in `ref-filter`. So I am thinking, how\n> can I find the performance\n> bottleneck in `ref-filter` and optimize it?\n>\n> So I try to find and use performance testing tools to analyze the\n> time-consuming steps of\n> `git cat-file --batch`.\n\nYeah, that's the right thing to do at this point!\n\n> * Using Google's `gperftools`:\n\n[...]\n\n> Ignore `write`, `inflate` and `000055d9164cdc36`, the execution time of `memcmp`\n> and `memmove` is very large.\n>\n> However, whether it is `git cat-file` before or after re-using the\n> `ref-filter` logic,\n> the functions they call take up similar proportions of time.\n\nYeah, it's not clear what is causing performance issues from this. It\nmay be that the issue is that with the ref-filter code more objects\nneed to be fully read. I wonder if there is a way to count that.\n\n> * Using `perf`:\n> `perf top -p <git-pid>`\n>\n> ```\n> 12.72% libc-2.33.so [.] __memmove_avx_unaligned_erms\n> 7.39% libz.so.1.2.11 [.] inflate\n> 5.56% libz.so.1.2.11 [.] 0x00000000000088ba\n> 5.27% libz.so.1.2.11 [.] adler32_z\n> 3.46% git [.] patch_delta\n> ```\n> We can see that `memmove` is still the part that accounts for the\n> largest proportion of time.\n\nYeah. Do you think that the code is calling memmove directly or\nthrough another function? And anyway which part of the code is\nresponsible for these calls?\n\nFlame graphs (http://www.brendangregg.com/flamegraphs.html) might help\nget a better idea of what happens.\n\n> We can already come to a conclusion: A lot of the time of `cat-file\n> --batch` is used for data copy,\n> this may be the focus of our later performance optimization.\n\nThanks!\n"},{"id":"428612","messageId":"CAOLTT8SFmPVm3SAt=QO9VVAZ=2EYUBb3TToe3tv=kuQTBrXq2w@mail.gmail.com","threadId":"56013","inReplyTo":"CAP8UFD0dDeL6crqqXPRd+564Z8n_EX3ctzRxKyGZFBp2SjbXEQ@mail.gmail.com","subject":"Re: [GSoC] Git Blog 6","fromName":"ZheNing Hu","fromEmail":"adlternative@gmail.com","sentAt":"2021-06-28T15:55:01Z","receivedAt":"2021-06-28T15:55:59Z","isPatch":false,"sender":{"key":"adlternative@gmail.com","avatar":"https://avatars.githubusercontent.com/u/58138461?v=4"},"body":"Christian Couder <christian.couder@gmail.com> 于2021年6月28日周一 上午5:53写道：\n>\n> > * Using Google's `gperftools`:\n>\n> [...]\n>\n> > Ignore `write`, `inflate` and `000055d9164cdc36`, the execution time of `memcmp`\n> > and `memmove` is very large.\n> >\n> > However, whether it is `git cat-file` before or after re-using the\n> > `ref-filter` logic,\n> > the functions they call take up similar proportions of time.\n>\n> Yeah, it's not clear what is causing performance issues from this. It\n> may be that the issue is that with the ref-filter code more objects\n> need to be fully read. I wonder if there is a way to count that.\n>\n\nYes, maybe we need more precise time, and if it can locate the function\nin git will be better.\n\n> > * Using `perf`:\n> > `perf top -p <git-pid>`\n> >\n> > ```\n> > 12.72% libc-2.33.so [.] __memmove_avx_unaligned_erms\n> > 7.39% libz.so.1.2.11 [.] inflate\n> > 5.56% libz.so.1.2.11 [.] 0x00000000000088ba\n> > 5.27% libz.so.1.2.11 [.] adler32_z\n> > 3.46% git [.] patch_delta\n> > ```\n> > We can see that `memmove` is still the part that accounts for the\n> > largest proportion of time.\n>\n> Yeah. Do you think that the code is calling memmove directly or\n> through another function? And anyway which part of the code is\n> responsible for these calls?\n>\n\nThere is no clear conclusion yet. But it is likely to be xmemdupz, xstrdup.\n\n\n> Flame graphs (http://www.brendangregg.com/flamegraphs.html) might help\n> get a better idea of what happens.\n>\n\nThanks, I will check if we can take use of it.\n\n> > We can already come to a conclusion: A lot of the time of `cat-file\n> > --batch` is used for data copy,\n> > this may be the focus of our later performance optimization.\n>\n> Thanks!\n\nThanks.\n--\nZheNing Hu\n"}]}