Re: [WIP/PATCH 7/6] perf: add a performance test for core.fsmonitor

From: Ben Peart <peartben@gmail.com>
Date: Jun 5, 2017, 14:27 UTC
Message-ID: <65158deb-981f-47f2-4ded-e5f691e2264f@gmail.com>
In-Reply-To: <75ecd288047648178ed93105ee1f7a9e@exmbdft7.ad.twosigma.com>

On 6/2/2017 5:44 PM, David Turner wrote:

Show 17 quoted lines

> BTW, a medium-sized (~250k files across 40k dirs) synthetic repo is available over bittorrent at:
> http://bitmover.com/2015-04-03-1M-git-bare.tar.bz2.torrent
> 
> I tried Ævar's perf test with that (on a beefy laptop with SSD), and got significantly slower results with bp/fsmonitor:
> Test                          origin/master     bp/fsmonitor
> -----------------------------------------------------------------------
> 7519.2: status (first)        0.32(0.23+0.39)   0.32(0.26+0.36) +0.0%
> 7519.3: status (subsequent)   0.18(0.14+0.34)   0.32(0.24+0.37) +77.8%
> 7519.4: status -uno           0.11(0.08+0.32)   0.24(0.18+0.34) +118.2%
> 7519.5: status -uall          0.49(0.22+0.56)   0.62(0.36+0.55) +26.5%
> 7519.2: status (first)        0.32(0.23+0.39)   0.32(0.26+0.36) +0.0%
> 7519.3: status (subsequent)   0.18(0.14+0.34)   0.32(0.24+0.37) +77.8%
> 7519.4: status -uno           0.11(0.08+0.32)   0.24(0.18+0.34) +118.2%
> 7519.5: status -uall          0.49(0.22+0.56)   0.62(0.36+0.55) +26.5%
> 
> I have not yet looked into why this is.
>

I was very focused on getting minute long status calls down to seconds and multiple seconds down to sub-second. The greatest benefits are when the file system cache doesn't already have all the file information cached and the current perf test doesn't test that case - just the warm cache test which has the least benefit.

That said, status times shouldn't be getting worse and this has highlighted that they are. I've found one reason (the current patch series always flags the index as dirty so it gets written out every time). I've got a fix that only flags it dirty when the extension is turned on or off or when it actually finds an entry that has become dirty. This helps but there is more going on than that.

I'm looking into why the minimum status time with fsmonitor turned on and a warm cache seems to be ~30ms. More to come...

Show 179 quoted lines

>> -----Original Message-----
>> From: Ævar Arnfjörð Bjarmason [mailto:avarab@gmail.com]
>> Sent: Friday, June 2, 2017 6:29 AM
>> To: git@vger.kernel.org
>> Cc: Junio C Hamano <gitster@pobox.com>; Ben Peart
>> <peartben@gmail.com>; Nguyễn Thái Ngọc Duy <pclouds@gmail.com>;
>> Johannes Schindelin <johannes.schindelin@gmx.de>; David Turner
>> <David.Turner@twosigma.com>; Jeff King <peff@peff.net>; Christian
>> Couder <christian.couder@gmail.com>; Ævar Arnfjörð Bjarmason
>> <avarab@gmail.com>
>> Subject: [WIP/PATCH 7/6] perf: add a performance test for core.fsmonitor
>>
>> Add a performance test for the new core.fsmonitor facility using the sample
>> query-fsmonitor hook.
>>
>> This is WIP code for the reasons explained in the setup comments,
>> unfortunately the perf code doesn't easily allow you to run different setup
>> code for different versions you're testing. This test will stop working if the
>> fsmonitor is merged into the master branch.
>>
>> Output against linxu.git:
>>
>>      $ GIT_PERF_REPEAT_COUNT=10 GIT_PERF_LARGE_REPO=~/g/linux
>> GIT_PERF_MAKE_OPTS='-j8' ./run origin/master avar/fsmonitor ./p7519-
>> fsmonitor.sh
>>      [...]
>>      Test                          origin/master     avar/fsmonitor
>>      -----------------------------------------------------------------------
>>      7519.2: status (first)        0.08(0.04+0.09)   0.12(0.07+0.10) +50.0%
>>      7519.3: status (subsequent)   0.08(0.04+0.09)   0.12(0.06+0.11) +50.0%
>>      7519.4: status -uno           0.02(0.02+0.05)   0.06(0.05+0.06) +200.0%
>>      7519.5: status -uall          0.08(0.06+0.07)   0.12(0.07+0.10) +50.0%
>>
>> And against a larger in-house monorepo I have here, with the same options
>> (except the repo path):
>>
>>      Test                          origin/master     avar/fsmonitor
>>      -----------------------------------------------------------------------
>>      7519.2: status (first)        0.20(0.11+0.18)   0.27(0.15+0.21) +35.0%
>>      7519.3: status (subsequent)   0.20(0.11+0.18)   0.27(0.15+0.21) +35.0%
>>      7519.4: status -uno           0.04(0.03+0.10)   0.22(0.08+0.12) +450.0%
>>      7519.5: status -uall          0.20(0.13+0.16)   0.27(0.18+0.19) +35.0%
>>
>> Against linux.git with a hack to flush the FS cache (on Linux) before running
>> the first 'git status', only running one test so the result isn't discarded as the
>> slowest of N:
>>
>>      $ GIT_PERF_REPEAT_COUNT=1 GIT_PERF_LARGE_REPO=~/g/linux
>> GIT_PERF_MAKE_COMMAND='sudo sync && echo 3 | sudo tee
>> /proc/sys/vm/drop_caches >/dev/null && make -j8' ./run origin/master
>> avar/fsmonitor ./p7519-fsmonitor.sh
>>      [...]
>>      Test                          origin/master     avar/fsmonitor
>>      ------------------------------------------------------------------------
>>      7519.2: status (first)        0.30(0.18+0.10)   8.26(0.22+0.10) +2653.3%
>>      7519.3: status (subsequent)   0.08(0.04+0.08)   0.81(0.09+0.07) +912.5%
>>      7519.4: status -uno           0.02(0.01+0.06)   0.08(0.04+0.07) +300.0%
>>      7519.5: status -uall          0.08(0.06+0.07)   0.15(0.08+0.09) +87.5%
>>
>> Now obviously due to 1 run that has a lot of noise, but I would expect that
>> first invocation to be blindingly fast since watchman has info on what files
>> were modified since the cache was flushed.
>>
>> The same on the large monorepo noted above:
>>
>>      Test                          origin/master     avar/fsmonitor
>>      -----------------------------------------------------------------------
>>      7519.2: status (first)        0.59(0.28+0.24)   0.93(0.35+0.19) +57.6%
>>      7519.3: status (subsequent)   0.20(0.10+0.19)   0.28(0.16+0.20) +40.0%
>>      7519.4: status -uno           0.04(0.04+0.09)   0.11(0.08+0.12) +175.0%
>>      7519.5: status -uall          0.29(0.11+0.18)   0.40(0.16+0.19) +37.9%
>>
>> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
>> ---
>>
>>
>> On Fri, Jun 2, 2017 at 2:40 AM, Ben Peart <peartben@gmail.com> wrote:
>>> Any chance you can provide me with a bash script that contains the
>>> exact sequence of commands you are running to get this result?  I've
>>> been trying to replicate it using your notes but have not been able
>>> to.  I'd like to see if it is a repo difference, a platform
>>> difference, a command sequence difference (or something else entirely
>> :)).
>>
>> I can do better than that, here's a new perf test on top of this series which
>> demonstates the issue. I've only tested this on Linux
>> 4.9.0 with watchman 4.9.0 compiled from git (yes, they're coincidentally the
>> same version).
>>
>> A good addition to this would be `printf <fmt for date N sec in the
>> past> | watchman -j` as noted in my earlier mail, but I ran out of
>> time.
>>
>> You can also set any combination of GIT_PERF_7519_UNTRACKED_CACHE &
>> GIT_PERF_7519_SPLIT_INDEX to play with turning that on. I haven't tested all
>> combinations of that, but e.g. testing with untrackedCache didn't give results
>> that looked different from the performance regressions noted above.
>>
>> Aside from performance, I think a very good addition to stress-test this series
>> would be a patch to t/test-lib*sh guarded by some env flag to do a similar
>> watchman watch-del/watch/watch-list dance as the one I'm doing here in
>> the setup, and setting up the hook / config.
>>
>> That would allow testing the entire git test suite with this feature, to find any
>> subtle bugs this might have introduced in git-status.
>>
>>   t/perf/p7519-fsmonitor.sh | 58
>> +++++++++++++++++++++++++++++++++++++++++++++++
>>   1 file changed, 58 insertions(+)
>>   create mode 100755 t/perf/p7519-fsmonitor.sh
>>
>> diff --git a/t/perf/p7519-fsmonitor.sh b/t/perf/p7519-fsmonitor.sh new file
>> mode 100755 index 0000000000..b838a0ff14
>> --- /dev/null
>> +++ b/t/perf/p7519-fsmonitor.sh
>> @@ -0,0 +1,58 @@
>> +#!/bin/sh
>> +
>> +test_description="Test core.fsmonitor"
>> +
>> +. ./perf-lib.sh
>> +
>> +test_perf_large_repo
>> +test_checkout_worktree
>> +
>> +test_expect_success 'setup' '
>> +	# Maybe set untrackedCache & splitIndex depending on the
>> +	# environment, defaulting to false.
>> +	if test -n "$GIT_PERF_7519_UNTRACKED_CACHE"
>> +	then
>> +		git config core.untrackedCache true
>> +	else
>> +		git config core.untrackedCache false
>> +	fi &&
>> +	if test -n "$GIT_PERF_7519_SPLIT_INDEX"
>> +	then
>> +		git config core.splitIndex true
>> +	else
>> +		git config core.splitIndex false
>> +	fi &&
>> +
>> +	# Relies on core.fsmonitor not being merged into master. Needs
>> +	# better per-test ways to disable it if it gets merged.
>> +	git config core.fsmonitor true &&
>> +
>> +	# Hook scaffolding
>> +	mkdir .git/hooks &&
>> +	cp ../../../templates/hooks--query-fsmonitor.sample
>> +.git/hooks/query-fsmonitor &&
>> +
>> +	# Setup watchman & ensure it is actually watching
>> +	watchman watch-del "$PWD" >/dev/null 2>&1 &&
>> +	watchman watch "$PWD" >/dev/null 2>&1 &&
>> +	watchman watch-list | grep -q -F "$PWD"
>> +'
>> +
>> +# Setting:
>> +#
>> +#    GIT_PERF_REPEAT_COUNT=1 GIT_PERF_MAKE_COMMAND='sudo sync
>> && echo 3 | sudo tee /proc/sys/vm/drop_caches && make -j8'
>> +#
>> +# Can be used as a hack to performance test 'git status' on a cold fs #
>> +cache with an existing watchman watching the directory, which should #
>> +be blindingly fast, compared to amazingly slow without watchman.
>> +test_perf 'status (first)'       'git status'
>> +
>> +
>> +# The same git-status once the fs cache has been warmed, if using the #
>> +GIT_PERF_MAKE_COMMAND above. Otherwise the same as above.
>> +test_perf 'status (subsequent)'  'git status'
>> +
>> +# Let's see if -uno & -uall make any difference
>> +test_perf 'status -uno'          'git status -uno'
>> +test_perf 'status -uall'         'git status -uall'
>> +
>> +test_done
>> --
>> 2.13.0.506.g27d5fe0cd
>