Mercurial > hg
view tests/test-profile.t @ 38781:0a57945aaf7f
manifest: persist the manifestfulltext cache
Reconstructing the manifest from the revlog takes time, so much so that there
already is a LRU cache to avoid having to load a manifest multiple times.
This patch persists that LRU cache in the .hg/cache directory, so we can re-use
this cache across hg commands. Commit benchmark (run on Macos 10.13 on a
2017-model Macbook Pro with Core i7 2.9GHz and flash drive), testing without
and with patch run 5 times, baseline is r2a227782e754:
* committing to an existing file, against the mozilla-central repository.
Baseline real time average 1.9692, with patch 1.3786.
A new debugcommand "hg debugmanifestfulltextcache" lets you inspect the cache,
clear it, or add specific manifest nodeids to it. When calling
repo.updatecaches(), the manifest(s) for the working copy parents are added to
the cache.
The hg perfmanifest command has an additional --clear-disk switch to clear this
cache when testing manifest loading performance.
Using this command to test performance on the firefox repository for revision
f947d902ed91, whose manifest has a delta chain length of 60540, we see:
$ hg perfmanifest f947d902ed91 --clear-disk
! wall 0.972253 comb 0.970000 user 0.850000 sys 0.120000 (best of 10)
$ hg debugmanifestfulltextcache -a `hg log --debug -r f947d902ed91 | grep manifest | cut -d: -f3`
Cache contains 1 manifest entries, in order of most to least recent:
id: 0294517df4aad07c70701db43bc7ff24c3ce7dbc, size 25.6 MB
Total cache data size 25.6 MB, on-disk 0 bytes
$ hg perfmanifest f947d902ed91
! wall 0.036748 comb 0.040000 user 0.020000 sys 0.020000 (best of 100)
Worst-case scenario: a manifest text loaded from a single delta; in the firefox
repository manifest node 9a1246ff762e is the chain base for the manifest
attached to revision f947d902ed91. Loading this from a full cache file is just
as fast as without the cache; the extra node ids ensure a big full cache:
$ for node in 9a1246ff762e 1a1922c14a3e 54a31d11a36a 0294517df4aa; do
> hgd debugmanifestfulltextcache -a $node > /dev/null
> done
$ hgd perfmanifest -m 9a1246ff762e
! wall 0.077513 comb 0.080000 user 0.030000 sys 0.050000 (best of 100)
$ hgd perfmanifest -m 9a1246ff762e --clear-disk
! wall 0.078547 comb 0.080000 user 0.070000 sys 0.010000 (best of 100)
author | Martijn Pieters <mj@zopatista.com> |
---|---|
date | Tue, 31 Jul 2018 19:37:54 +0200 |
parents | fd8eedcc3fd2 |
children | 5abc47d4ca6b |
line wrap: on
line source
test --time $ hg --time help -q help 2>&1 | grep time > /dev/null $ hg init a $ cd a Function to check that statprof ran $ statprofran () { > egrep 'Sample count:|No samples recorded' > /dev/null > } test --profile $ hg st --profile 2>&1 | statprofran Abreviated version $ hg st --prof 2>&1 | statprofran In alias $ hg --config "alias.profst=status --profile" profst 2>&1 | statprofran #if lsprof $ prof='hg --config profiling.type=ls --profile' $ $prof st 2>../out $ grep CallCount ../out > /dev/null || cat ../out $ $prof --config profiling.output=../out st $ grep CallCount ../out > /dev/null || cat ../out $ $prof --config profiling.output=blackbox --config extensions.blackbox= st $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log $ $prof --config profiling.format=text st 2>../out $ grep CallCount ../out > /dev/null || cat ../out $ echo "[profiling]" >> $HGRCPATH $ echo "format=kcachegrind" >> $HGRCPATH $ $prof st 2>../out $ grep 'events: Ticks' ../out > /dev/null || cat ../out $ $prof --config profiling.output=../out st $ grep 'events: Ticks' ../out > /dev/null || cat ../out #endif #if lsprof serve Profiling of HTTP requests works $ $prof --config profiling.format=text --config profiling.output=../profile.log serve -d -p $HGPORT --pid-file ../hg.pid -A ../access.log $ cat ../hg.pid >> $DAEMON_PIDS $ hg -q clone -U http://localhost:$HGPORT ../clone A single profile is logged because file logging doesn't append $ grep CallCount ../profile.log | wc -l \s*1 (re) #endif Install an extension that can sleep and guarantee a profiler has time to run $ cat >> sleepext.py << EOF > import time > from mercurial import registrar, commands > cmdtable = {} > command = registrar.command(cmdtable) > @command(b'sleep', [], b'hg sleep') > def sleep(ui, *args, **kwargs): > time.sleep(0.1) > EOF $ cat >> $HGRCPATH << EOF > [extensions] > sleep = `pwd`/sleepext.py > EOF statistical profiler works $ hg --profile sleep 2>../out $ cat ../out | statprofran Various statprof formatters work $ hg --profile --config profiling.statformat=byline sleep 2>../out $ head -n 1 ../out % cumulative self $ cat ../out | statprofran $ hg --profile --config profiling.statformat=bymethod sleep 2>../out $ head -n 1 ../out % cumulative self $ cat ../out | statprofran $ hg --profile --config profiling.statformat=hotpath sleep 2>../out $ cat ../out | statprofran $ hg --profile --config profiling.statformat=json sleep 2>../out $ cat ../out \[\[-?\d+.* (re) statprof can be used as a standalone module $ $PYTHON -m mercurial.statprof hotpath must specify --file to load [1] $ cd .. #if no-chg profiler extension could be loaded before other extensions $ cat > fooprof.py <<EOF > from __future__ import absolute_import > import contextlib > @contextlib.contextmanager > def profile(ui, fp): > print('fooprof: start profile') > yield > print('fooprof: end profile') > def extsetup(ui): > ui.write(b'fooprof: loaded\n') > EOF $ cat > otherextension.py <<EOF > from __future__ import absolute_import > def extsetup(ui): > ui.write(b'otherextension: loaded\n') > EOF $ hg init b $ cd b $ cat >> .hg/hgrc <<EOF > [extensions] > other = $TESTTMP/otherextension.py > fooprof = $TESTTMP/fooprof.py > EOF $ hg root otherextension: loaded fooprof: loaded $TESTTMP/b $ HGPROF=fooprof hg root --profile fooprof: loaded fooprof: start profile otherextension: loaded $TESTTMP/b fooprof: end profile $ HGPROF=other hg root --profile 2>&1 | head -n 2 otherextension: loaded unrecognized profiler 'other' - ignored $ HGPROF=unknown hg root --profile 2>&1 | head -n 1 unrecognized profiler 'unknown' - ignored $ cd .. #endif