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

[Ben Peart <peartben@gmail.com>]

On 6/2/2017 5:44 PM, David Turner wrote:
> 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...

>> -----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
>