tests/test-profile.t
author spectral <spectral@google.com>
Thu, 27 Sep 2018 20:16:48 -0700
changeset 39985 731961d972ba
parent 39723 5abc47d4ca6b
child 40200 9cc411952ab9
permissions -rw-r--r--
treemanifests: remove _loadalllazy in _diff() The benchmarks below use a similar setup as in ee7ee0c516ca and my other recent commits. Yes, in some cases this runs in literally 5% of the time it previously took. before = a6f8ab53 diff --git: repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before ------+---+---+------------------------+-----------------------+------------ m-u | | | 1.301 s +- 0.004 s | 1.309 s +- 0.012 s | 100.6% m-u | | x | 1.303 s +- 0.009 s | 1.302 s +- 0.006 s | 99.9% m-u | x | | 1.308 s +- 0.006 s | 1.309 s +- 0.007 s | 100.1% m-u | x | x | 85.7 ms +- 0.6 ms | 86.0 ms +- 0.3 ms | 100.4% l-d-r | | | 197.5 ms +- 0.7 ms | 197.8 ms +- 2.2 ms | 100.2% l-d-r | | x | 199.4 ms +- 0.6 ms | 199.3 ms +- 0.9 ms | 99.9% l-d-r | x | | 86.1 ms +- 0.5 ms | 85.8 ms +- 0.9 ms | 99.7% l-d-r | x | x | 64.4 ms +- 0.4 ms | 64.4 ms +- 0.3 ms | 100.0% diff -c . --git: repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before ------+---+---+------------------------+-----------------------+------------ m-u | | | 236.7 ms +- 1.1 ms | 236.5 ms +- 1.3 ms | 99.9% m-u | | x | 158.7 ms +- 1.0 ms | 128.0 ms +- 1.0 ms | 80.7% <-- m-u | x | | 239.7 ms +- 1.8 ms | 238.1 ms +- 1.5 ms | 99.3% m-u | x | x | 132.4 ms +- 0.9 ms | 132.3 ms +- 0.6 ms | 99.9% l-d-r | | | 81.8 ms +- 0.4 ms | 81.8 ms +- 0.3 ms | 100.0% l-d-r | | x | 3.894 s +- 0.017 s | 193.6 ms +- 0.4 ms | 5.0% <-- l-d-r | x | | 106.9 ms +- 0.4 ms | 106.6 ms +- 0.3 ms | 99.7% l-d-r | x | x | 182.7 ms +- 0.8 ms | 183.3 ms +- 0.9 ms | 100.3% rebase -r . --keep -d .^^: repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before ------+---+---+------------------------+-----------------------+------------ m-u | | | 5.615 s +- 0.109 s | 5.562 s +- 0.015 s | 99.1% m-u | | x | 5.701 s +- 0.027 s | 5.715 s +- 0.023 s | 100.2% m-u | x | | 5.572 s +- 0.128 s | 5.613 s +- 0.182 s | 100.7% m-u | x | x | 633.3 ms +- 28.7 ms | 636.2 ms +- 13.8 ms | 100.5% l-d-r | | | 666.4 ms +- 17.0 ms | 658.5 ms +- 9.3 ms | 98.8% l-d-r | | x | 6.520 s +- 0.070 s | 6.505 s +- 0.026 s | 99.8% l-d-r | x | | 279.0 ms +- 13.0 ms | 276.5 ms +- 4.7 ms | 99.1% l-d-r | x | x | 1.636 s +- 0.058 s | 1.657 s +- 0.014 s | 101.3% status --change . --copies: repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before ------+---+---+------------------------+-----------------------+------------ m-u | | | 218.6 ms +- 1.4 ms | 217.9 ms +- 1.5 ms | 99.7% m-u | | x | 138.5 ms +- 0.4 ms | 108.4 ms +- 0.2 ms | 78.3% <-- m-u | x | | 220.1 ms +- 1.3 ms | 219.7 ms +- 1.5 ms | 99.8% m-u | x | x | 113.2 ms +- 0.4 ms | 112.4 ms +- 0.8 ms | 99.3% l-d-r | | | 80.2 ms +- 0.3 ms | 80.6 ms +- 0.6 ms | 100.5% l-d-r | | x | 3.899 s +- 0.020 s | 194.8 ms +- 4.0 ms | 5.0% <-- l-d-r | x | | 83.4 ms +- 0.8 ms | 83.2 ms +- 0.2 ms | 99.8% l-d-r | x | x | 732.2 ms +- 4.3 ms | 194.9 ms +- 1.0 ms | 26.6% <-- status --copies: repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before ------+---+---+------------------------+-----------------------+------------ m-u | | | 1.917 s +- 0.005 s | 1.914 s +- 0.004 s | 99.8% m-u | | x | 1.909 s +- 0.012 s | 1.934 s +- 0.004 s | 101.3% m-u | x | | 1.915 s +- 0.005 s | 1.904 s +- 0.004 s | 99.4% m-u | x | x | 94.8 ms +- 0.3 ms | 94.7 ms +- 0.2 ms | 99.9% l-d-r | | | 593.9 ms +- 1.2 ms | 594.6 ms +- 9.4 ms | 100.1% l-d-r | | x | 595.2 ms +- 3.8 ms | 597.2 ms +- 2.6 ms | 100.3% l-d-r | x | | 182.5 ms +- 1.6 ms | 182.1 ms +- 0.6 ms | 99.8% l-d-r | x | x | 149.6 ms +- 0.9 ms | 149.1 ms +- 0.8 ms | 99.7% update $rev^; ~/src/hg/hg{hg}/hg update $rev: repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before ------+---+---+------------------------+-----------------------+------------ m-u | | | 3.121 s +- 0.007 s | 3.129 s +- 0.012 s | 100.3% m-u | | x | 2.972 s +- 0.011 s | 2.981 s +- 0.012 s | 100.3% m-u | x | | 3.144 s +- 0.014 s | 3.141 s +- 0.011 s | 99.9% m-u | x | x | 312.2 ms +- 2.4 ms | 312.3 ms +- 2.1 ms | 100.0% l-d-r | | | 444.4 ms +- 4.3 ms | 446.9 ms +- 5.3 ms | 100.6% l-d-r | | x | 9.159 s +- 0.069 s | 9.182 s +- 0.040 s | 100.3% l-d-r | x | | 254.6 ms +- 1.6 ms | 255.2 ms +- 1.6 ms | 100.2% l-d-r | x | x | 1.525 s +- 0.007 s | 1.577 s +- 0.007 s | 103.4% <--? Differential Revision: https://phab.mercurial-scm.org/D4845

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