statprof: separate functions and "line", assume 4 digit line numbers
Previously, the profile output looked like this (I've removed many lines that
are mostly inconsequential):
```
| 100.0% 0.02s hg: <module> line 43: dispatch.run()
| 100.0% 0.02s dispatch.py: run line 115: status = dispatch(req)
| 100.0% 0.02s dispatch.py: _runcatchfunc line 432: return _dispatch(req)
\ 50.0% 0.01s dispatch.py: _dispatch line 1228: return runcommand(
| 50.0% 0.01s dispatch.py: runcommand line 883: ret = _runcommand(ui, optio...
| 50.0% 0.01s dispatch.py: _runcommand line 1240: return cmdfunc()
| 50.0% 0.01s localrepo.py: __getitem__ line 1670: quick_access = self._quick_...
| 50.0% 0.01s localrepo.py: _quick_access_changeidline 1650: return self._quick_access_c...
| 50.0% 0.01s localrepo.py: __get__ line 179: return getattr(unfi, self.n...
| 50.0% 0.01s util.py: __get__ line 1747: result = self.func(obj)
| 50.0% 0.01s localrepo.py: _quick_access_changeid_wcline 1611: cl = self.unfiltered().chan...
| 50.0% 0.01s localrepo.py: __get__ line 110: return super(_basefilecache...
| 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 783:
| 50.0% 0.01s <frozen importlib._bootstrap>: _call_with_frames_removedline 219:
| 50.0% 0.01s changelog.py: <module> line 376: class changelog(revlog.revl...
| 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 779:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: get_codeline 868:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: path_statsline 1012:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: _path_statline 87:
```
This has a few problems, though I'm only addressing some of them.
1. If the stuff before "line ###" is long, there's no separation between the
function name and the "line" string.
2. If the stuff before "line ###" is really long, there's excessive separation
between the "line" string and the line number.
3. We frequently have 4-digit line numbers, the code on the right wasn't
dynamically indented and ended up quite messy looking.
To solve these problems, I've added a ", " prefix before "line" iff it would
otherwise not have any separation such as spaces. I've added a 'max' so that we
never use a negative width (which is the cause of problem #2 above), and I've
added a default assumption of 4 digit line numbers (but again using a 'max' so
this shouldn't cause problems if we go beyond that.
With these changes, it now looks like this:
```
| 100.0% 0.02s hg: <module> line 43: dispatch.run()
| 100.0% 0.02s dispatch.py: run line 115: status = dispatch(req)
| 100.0% 0.02s dispatch.py: _runcatchfunc line 432: return _dispatch(req)
\ 50.0% 0.01s dispatch.py: _dispatch line 1228: return runcommand(
| 50.0% 0.01s dispatch.py: runcommand line 883: ret = _runcommand(ui, optio...
| 50.0% 0.01s dispatch.py: _runcommand line 1240: return cmdfunc()
| 50.0% 0.01s localrepo.py: __getitem__ line 1670: quick_access = self._quick_...
| 50.0% 0.01s localrepo.py: _quick_access_changeid, line 1650: return self._quick_access_c...
| 50.0% 0.01s localrepo.py: __get__ line 179: return getattr(unfi, self.n...
| 50.0% 0.01s util.py: __get__ line 1747: result = self.func(obj)
| 50.0% 0.01s localrepo.py: _quick_access_changeid_wc, line 1611: cl = self.unfiltered().chan...
| 50.0% 0.01s localrepo.py: __get__ line 110: return super(_basefilecache...
| 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_module, line 783:
| 50.0% 0.01s <frozen importlib._bootstrap>: _call_with_frames_removed, line 219:
| 50.0% 0.01s changelog.py: <module> line 376: class changelog(revlog.revl...
| 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_module, line 779:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: get_code, line 868:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: path_stats, line 1012:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: _path_stat, line 87:
```
Differential Revision: https://phab.mercurial-scm.org/D9511
#!/usr/bin/env python3
#
# hgperf - measure performance of Mercurial commands
#
# Copyright 2014 Matt Mackall <mpm@selenic.com>
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.
'''measure performance of Mercurial commands
Using ``hgperf`` instead of ``hg`` measures performance of the target
Mercurial command. For example, the execution below measures
performance of :hg:`heads --topo`::
$ hgperf heads --topo
All command output via ``ui`` is suppressed, and just measurement
result is displayed: see also "perf" extension in "contrib".
Costs of processing before dispatching to the command function like
below are not measured::
- parsing command line (e.g. option validity check)
- reading configuration files in
But ``pre-`` and ``post-`` hook invocation for the target command is
measured, even though these are invoked before or after dispatching to
the command function, because these may be required to repeat
execution of the target command correctly.
'''
import os
import sys
libdir = '@LIBDIR@'
if libdir != '@' 'LIBDIR' '@':
if not os.path.isabs(libdir):
libdir = os.path.join(
os.path.dirname(os.path.realpath(__file__)), libdir
)
libdir = os.path.abspath(libdir)
sys.path.insert(0, libdir)
# enable importing on demand to reduce startup time
try:
from mercurial import demandimport
demandimport.enable()
except ImportError:
import sys
sys.stderr.write(
"abort: couldn't find mercurial libraries in [%s]\n"
% ' '.join(sys.path)
)
sys.stderr.write("(check your install and PYTHONPATH)\n")
sys.exit(-1)
from mercurial import (
dispatch,
util,
)
def timer(func, title=None):
results = []
begin = util.timer()
count = 0
while True:
ostart = os.times()
cstart = util.timer()
r = func()
cstop = util.timer()
ostop = os.times()
count += 1
a, b = ostart, ostop
results.append((cstop - cstart, b[0] - a[0], b[1] - a[1]))
if cstop - begin > 3 and count >= 100:
break
if cstop - begin > 10 and count >= 3:
break
if title:
sys.stderr.write("! %s\n" % title)
if r:
sys.stderr.write("! result: %s\n" % r)
m = min(results)
sys.stderr.write(
"! wall %f comb %f user %f sys %f (best of %d)\n"
% (m[0], m[1] + m[2], m[1], m[2], count)
)
orgruncommand = dispatch.runcommand
def runcommand(lui, repo, cmd, fullargs, ui, options, d, cmdpats, cmdoptions):
ui.pushbuffer()
lui.pushbuffer()
timer(
lambda: orgruncommand(
lui, repo, cmd, fullargs, ui, options, d, cmdpats, cmdoptions
)
)
ui.popbuffer()
lui.popbuffer()
dispatch.runcommand = runcommand
dispatch.run()