view tests/test-profile.t @ 43271:99394e6c5d12

rust-dirstate-status: add first Rust implementation of `dirstate.status`

Note: This patch also added the rayon crate as a Cargo dependency. It will
help us immensely in making Rust code parallel and easy to maintain. It is
a stable, well-known, and supported crate maintained by people on the Rust
team.

The current `dirstate.status` method has grown over the years through bug
reports and new features to the point where it got too big and too complex.

This series does not yet improve the logic, but adds a Rust fast-path to speed
up certain cases.

Tested on mozilla-try-2019-02-18 with zstd compression:
    - `hg diff` on an empty working copy:
        - c: 1.64(+-)0.04s
        - rust+c before this change: 2.84(+-)0.1s
        - rust+c: 849(+-)40ms
    - `hg commit` when creating a file:
        - c: 5.960s
        - rust+c before this change: 5.828s
        - rust+c: 4.668s
    - `hg commit` when updating a file:
        - c: 4.866s
        - rust+c before this change: 4.371s
        - rust+c: 3.855s
    - `hg status -mard`
        - c: 1.82(+-)0.04s
        - rust+c before this change: 2.64(+-)0.1s
        - rust+c: 896(+-)30ms

The numbers are clear: the current Rust `dirstatemap` implementation is super
slow, its performance needs to be addressed.
This will be done in a future series, immediately after this one, with the goal
of getting Rust to be at least to the speed of the Python + C implementation
in all cases before the 5.2 freeze. At worse, we gate dirstatemap to only be used
in those cases.

Cases where the fast-path is not executed:
    - for commands that need ignore support (`status`, for example)
    - if subrepos are found (should not be hard to add, but winter is coming)
    - any other matcher than an `alwaysmatcher`, like patterns, etc.
    - with extensions like `sparse` and `fsmonitor`

The next step after this is to rethink the logic to be closer to
Jane Street's Valentin Gatien-Baron's Rust fast-path which does a lot less
work when possible.

Differential Revision: https://phab.mercurial-scm.org/D7058

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
  > 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 || cat ../out
  $ head -n 3 ../out
    %   cumulative      self          
   time    seconds   seconds  name    
  * sleepext.py:*:sleep (glob)
  $ cat ../out | statprofran

  $ hg --profile --config profiling.statformat=bymethod sleep 2>../out || cat ../out
  $ head -n 1 ../out
    %   cumulative      self          
  $ cat ../out | statprofran

  $ hg --profile --config profiling.statformat=hotpath sleep 2>../out || cat ../out
  $ cat ../out | statprofran

  $ hg --profile --config profiling.statformat=json sleep 2>../out || cat ../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
  > import sys
  > @contextlib.contextmanager
  > def profile(ui, fp):
  >     print('fooprof: start profile')
  >     sys.stdout.flush()
  >     yield
  >     print('fooprof: end profile')
  >     sys.stdout.flush()
  > 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