Git Mailing List Archive on lore.kernel.org
 help / color / Atom feed
From: "Ævar Arnfjörð Bjarmason" <avarab@gmail.com>
To: Duy Nguyen <pclouds@gmail.com>
Cc: git <git@vger.kernel.org>, Ben Peart <benpeart@microsoft.com>,
	Alex Vandiver <alexmv@dropbox.com>,
	Christian Couder <christian.couder@gmail.com>,
	David Turner <dturner@twopensource.com>
Subject: Re: Some rough edges of core.fsmonitor
Date: Sat, 27 Jan 2018 12:43:41 +0100
Message-ID: <87bmhfwmqa.fsf@evledraar.gmail.com> (raw)
In-Reply-To: <CACsJy8BpO0s6facg+zcKC9icijpefkipM326n6xOArjn=ZW6+w@mail.gmail.com>


On Sat, Jan 27 2018, Duy Nguyen jotted:

> 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

  parent reply index

Thread overview: 29+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2018-01-27  0:28 Ævar Arnfjörð Bjarmason
2018-01-27  1:36 ` Duy Nguyen
2018-01-27  1:39   ` [PATCH] trace: measure where the time is spent in the index-heavy operations Nguyễn Thái Ngọc Duy
2018-01-27 11:43   ` Ævar Arnfjörð Bjarmason [this message]
2018-01-27 12:39     ` Some rough edges of core.fsmonitor Duy Nguyen
2018-01-27 13:09       ` Duy Nguyen
2018-01-27 19:01         ` Ævar Arnfjörð Bjarmason
2018-01-30 22:41           ` Ben Peart
2018-01-29  9:40     ` Duy Nguyen
2018-01-29 23:16       ` Ben Peart
2018-02-01 10:40         ` Duy Nguyen
2018-01-28 20:44 ` Johannes Schindelin
2018-01-28 22:28   ` Ævar Arnfjörð Bjarmason
2018-01-30  1:21     ` Ben Peart
2018-01-31 10:15       ` Duy Nguyen
2018-02-04  9:38         ` [PATCH] dir.c: ignore paths containing .git when invalidating untracked cache Nguyễn Thái Ngọc Duy
2018-02-05 17:44           ` Ben Peart
2018-02-06 12:02             ` Duy Nguyen
2018-02-07  9:21           ` [PATCH v2] " Nguyễn Thái Ngọc Duy
2018-02-07  9:21             ` Nguyễn Thái Ngọc Duy
2018-02-07 16:59               ` Ben Peart
2018-02-13 10:00                 ` Duy Nguyen
2018-02-13 17:57                   ` Junio C Hamano
2018-02-14  1:24                     ` Duy Nguyen
2018-02-14  8:00                       ` Junio C Hamano
2018-01-30 22:57 ` Some rough edges of core.fsmonitor Ben Peart
2018-01-30 23:16   ` Ævar Arnfjörð Bjarmason
2018-01-31 16:12     ` Ben Peart
2018-01-27 11:58 [PATCH] trace: measure where the time is spent in the index-heavy operations Thomas Gummerer
2018-01-27 12:27 ` [PATCH v2] " Nguyễn Thái Ngọc Duy

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=87bmhfwmqa.fsf@evledraar.gmail.com \
    --to=avarab@gmail.com \
    --cc=alexmv@dropbox.com \
    --cc=benpeart@microsoft.com \
    --cc=christian.couder@gmail.com \
    --cc=dturner@twopensource.com \
    --cc=git@vger.kernel.org \
    --cc=pclouds@gmail.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

Git Mailing List Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/git/0 git/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 git git/ https://lore.kernel.org/git \
		git@vger.kernel.org
	public-inbox-index git

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.git


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git