Re: Some rough edges of core.fsmonitor

From: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
Date: Jan 27, 2018, 11:43 UTC
Message-ID: <87bmhfwmqa.fsf@evledraar.gmail.com>
In-Reply-To: <CACsJy8BpO0s6facg+zcKC9icijpefkipM326n6xOArjn=ZW6+w@mail.gmail.com>

On Sat, Jan 27 2018, Duy Nguyen jotted:

Show 47 quoted lines

> On Sat, Jan 27, 2018 at 7:28 AM, Ævar Arnfjörð Bjarmason
> <avarab@gmail.com> 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@gmail.com/
>
> 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