tests/test-profile.t

statprof: fix off-by-one-line error in output

martinvonz claims they thought that this was intentional, but couldn't remember
the reasoning for it. I can't understand why it would be preferable, and I
didn't see anything in the comments in the file about why this would be useful,
so I'm hopefully not breaking anything by "fixing" it.

### Old output

```
| 100.0%  0.01s  dispatch.py:    run               line 43:  dispatch.run()
| 100.0%  0.01s  dispatch.py:    dispatch          line 115:  status = dispatch(req)
| 100.0%  0.01s  dispatch.py:    _runcatch         line 266:  ret = _runcatch(req) or 0
| 100.0%  0.01s  dispatch.py:    _callcatch        line 442:  return _callcatch(ui, _runc...
| 100.0%  0.01s  scmutil.py:     callcatch         line 451:  return scmutil.callcatch(ui...
| 100.0%  0.01s  dispatch.py:    _runcatchfunc     line 155:  return func()
| 100.0%  0.01s  dispatch.py:    _dispatch         line 432:  return _dispatch(req)
| 100.0%  0.01s  hg.py:          repository        line 1179:  repo = hg.repository(
| 100.0%  0.01s  hg.py:          _peerorrepo       line 221:  peer = _peerorrepo(
| 100.0%  0.01s  util.py:        __getattribute__  line 188:  obj = _peerlookup(path).ins...
| 100.0%  0.01s  localrepo.py:   makelocalrepositoryline 3227:  return makelocalrepository(...
| 100.0%  0.01s  localrepo.py:   __init__          line 683:  return cls(
| 100.0%  0.01s  util.py:        __getattribute__  line 1262:  self._extrafilterid = repov...
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: exec_moduleline          245:  self.__spec__.loader.exec_m...
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: get_codeline       779:
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: path_statsline         868:
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: _path_statline         1012:
```

### New output

```
| 100.0%  0.01s  hg:             <module>          line 43:  dispatch.run()
| 100.0%  0.01s  dispatch.py:    run               line 115:  status = dispatch(req)
| 100.0%  0.01s  dispatch.py:    dispatch          line 266:  ret = _runcatch(req) or 0
| 100.0%  0.01s  dispatch.py:    _runcatch         line 442:  return _callcatch(ui, _runc...
| 100.0%  0.01s  dispatch.py:    _callcatch        line 451:  return scmutil.callcatch(ui...
| 100.0%  0.01s  scmutil.py:     callcatch         line 155:  return func()
| 100.0%  0.01s  dispatch.py:    _runcatchfunc     line 432:  return _dispatch(req)
| 100.0%  0.01s  dispatch.py:    _dispatch         line 1179:  repo = hg.repository(
| 100.0%  0.01s  hg.py:          repository        line 221:  peer = _peerorrepo(
| 100.0%  0.01s  hg.py:          _peerorrepo       line 188:  obj = _peerlookup(path).ins...
| 100.0%  0.01s  localrepo.py:   instance          line 3227:  return makelocalrepository(...
| 100.0%  0.01s  localrepo.py:   makelocalrepositoryline 683:  return cls(
| 100.0%  0.01s  localrepo.py:   __init__          line 1262:  self._extrafilterid = repov...
| 100.0%  0.01s  util.py:        __getattribute__  line 245:  self.__spec__.loader.exec_m...
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: exec_moduleline          779:
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: get_codeline       868:
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: path_statsline         1012:
| 100.0%  0.01s  <frozen importlib._bootstrap_external>: _path_statline         87:
```

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

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
  $ grep -v _path_stat ../out | head -n 3
    %   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
  $ grep sleepext.py ../out
  .* [0-9.]+%  [0-9.]+s  sleepext.py:\s*sleep           line 7:  time\.sleep.* (re)

  $ 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