On Sat, Jan 27 2018, Duy Nguyen jotted: > On Sat, Jan 27, 2018 at 7:28 AM, Ævar Arnfjörð Bjarmason > <avarab@xxxxxxxxx> wrote: >> 3) A lot of time spend reading the index (or something..) > > I'm resending a patch from my old index-helper series. It should > measure all big time consuming blocks in git. Maybe we should get it > merged... > >> While the hook itself takes ~20ms (and watchman itself 1/4 of that) >> status as a whole takes much longer. gprof reveals: >> >> Each sample counts as 0.01 seconds. >> % cumulative self self total >> time seconds seconds calls ms/call ms/call name >> 15.38 0.02 0.02 221690 0.00 0.00 memihash > > This sounds like name-hash to me. > >> 15.38 0.04 0.02 221689 0.00 0.00 create_from_disk >> 7.69 0.05 0.01 2216897 0.00 0.00 git_bswap32 >> 7.69 0.06 0.01 222661 0.00 0.00 ce_path_match >> 7.69 0.07 0.01 221769 0.00 0.00 hashmap_add >> 7.69 0.08 0.01 39941 0.00 0.00 prep_exclude >> 7.69 0.09 0.01 39940 0.00 0.00 strbuf_addch >> 7.69 0.10 0.01 1 10.00 10.00 read_one >> 7.69 0.11 0.01 1 10.00 10.00 refresh_index >> 7.69 0.12 0.01 1 10.00 10.00 tweak_fsmonitor >> 7.69 0.13 0.01 preload_thread >> >> The index is 24M in this case, I guess it's unpacking it, but I wonder >> if this couldn't be much faster if we saved away the result of the last >> "status" in something that's quick to access, and then if nothing > > No we could do better, we could cache parsed index content so > everybody benefits. I demonstrated it with my "index v254" patch a > while back: > > https://public-inbox.org/git/1399980019-8706-1-git-send-email-pclouds@xxxxxxxxx/ > > With the patch I'm sending soon, we can see how much time reading an > index take out of that ~140-150ms (and we probably can cut down index > read time to like 10-20% when cached). > >> changed we just report that, and no need to re-write the index (or just >> write the "it was clean at this time" part). > > Hmm.. does an index write increase that much time? Your patch is very useful. Here's (with gcc -03) some runtimes. This also includes my .git exclusion patch. These are all best out of 5, and with the top (until <0.5% time) of strace -c output (run as another invocation, timing not done with strace):: a) no fsmonitor $ time GIT_TRACE_PERFORMANCE=1 ~/g/git/git-status 12:32:44.947651 read-cache.c:1890 performance: 0.053153609 s: read cache .git/index 12:32:44.967943 preload-index.c:112 performance: 0.020161093 s: preload index 12:32:44.974217 read-cache.c:1446 performance: 0.006230611 s: refresh index 12:32:44.979083 diff-lib.c:250 performance: 0.004649994 s: diff-files 12:32:44.982511 diff-lib.c:527 performance: 0.002918416 s: diff-index 12:32:45.037880 dir.c:2290 performance: 0.055331063 s: read directory On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean 12:32:45.040666 trace.c:417 performance: 0.146724289 s: git command: '/home/aearnfjord/g/git/git-status' real 0m0.153s user 0m0.110s sys 0m0.354s % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 59.93 0.031924 1 39978 9 stat 35.86 0.019104 6368 3 futex 0.84 0.000446 12 36 mprotect 0.73 0.000389 13 29 munmap 0.66 0.000349 6 62 mmap 0.53 0.000285 14 20 clone b) with fsmonitor $ time GIT_TRACE_PERFORMANCE=1 ~/g/git/git-status 12:34:23.833625 read-cache.c:1890 performance: 0.049485685 s: read cache .git/index 12:34:23.838622 preload-index.c:112 performance: 0.001221197 s: preload index 12:34:23.858723 fsmonitor.c:170 performance: 0.020059647 s: fsmonitor process '.git/hooks/fsmonitor-watchman' 12:34:23.871532 read-cache.c:1446 performance: 0.032870818 s: refresh index 12:34:23.876427 diff-lib.c:250 performance: 0.004731427 s: diff-files 12:34:23.880669 diff-lib.c:527 performance: 0.003944422 s: diff-index 12:34:23.899225 dir.c:2290 performance: 0.018509066 s: read directory On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean 12:34:23.901914 trace.c:417 performance: 0.118250995 s: git command: '/home/aearnfjord/g/git/git-status' real 0m0.125s user 0m0.086s sys 0m0.043s % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 36.61 0.001281 61 21 clone 33.84 0.001184 41 29 munmap 5.09 0.000178 5 36 mprotect 4.34 0.000152 0 619 brk 4.17 0.000146 2 62 mmap 3.34 0.000117 2 55 20 open 3.00 0.000105 2 60 27 lstat 1.77 0.000062 2 37 9 stat 1.60 0.000056 1 51 read 1.57 0.000055 5 12 write 1.17 0.000041 41 1 wait4 0.83 0.000029 1 41 close 0.83 0.000029 1 22 getcwd 0.80 0.000028 1 34 fstat c) with fsmonitor + don't write index $ time GIT_TRACE_PERFORMANCE=1 GIT_OPTIONAL_LOCKS=0 ~/g/git/git-status 12:36:03.176866 read-cache.c:1890 performance: 0.048292088 s: read cache .git/index 12:36:03.181006 preload-index.c:112 performance: 0.001343593 s: preload index 12:36:03.200970 fsmonitor.c:170 performance: 0.019936338 s: fsmonitor process '.git/hooks/fsmonitor-watchman' 12:36:03.210556 read-cache.c:1446 performance: 0.029525531 s: refresh index 12:36:03.213366 diff-lib.c:250 performance: 0.002718730 s: diff-files 12:36:03.216273 diff-lib.c:527 performance: 0.002666604 s: diff-index 12:36:03.233579 dir.c:2290 performance: 0.017261702 s: read directory On branch master Your branch is up to date with 'origin/master'. nothing to commit, working tree clean 12:36:03.233733 trace.c:417 performance: 0.105632105 s: git command: '/home/aearnfjord/g/git/git-status' real 0m0.111s user 0m0.073s sys 0m0.044s % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 24.42 0.001081 37 29 munmap 20.74 0.000918 44 21 clone 7.63 0.000338 5 62 mmap 7.43 0.000329 6 54 20 open 6.05 0.000268 7 36 mprotect 5.99 0.000265 0 619 brk 4.99 0.000221 4 60 27 lstat 4.13 0.000183 4 51 read 3.68 0.000163 9 19 10 access 3.25 0.000144 4 34 fstat 2.78 0.000123 3 40 close 2.48 0.000110 3 37 9 stat 2.24 0.000099 5 21 getcwd 1.15 0.000051 4 12 write 0.99 0.000044 22 2 poll For comparison just the output from the hook: $ time ('.git/hooks/fsmonitor-watchman' '1' '1517052856494406191') .git real 0m0.017s user 0m0.011s sys 0m0.003s And this is what goes on behind the scenes after we get rid of the .git/hooks/fsmonitor-watchman overhead: $ time (echo '["query", "/home/aearnfjord/git_tree/2015-04-03-1M-git", { "since": 1517052856, "fields": ["name"], "expression": ["not", ["allof", ["since", 1517052856, "cclock"], ["not", "exists"]]] }]' | watchman -j) { "version": "4.9.0", "is_fresh_instance": false, "clock": "c:1517006351:31165:4:1113968", "files": [ ".git" ] } real 0m0.003s user 0m0.000s sys 0m0.004s
