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
--- a/mercurial/statprof.py Wed Dec 02 15:38:05 2020 -0800
+++ b/mercurial/statprof.py Wed Dec 02 12:33:51 2020 -0800
@@ -768,10 +768,18 @@
filename,
function,
)
- codepattern = b'%' + (b'%d' % (55 - len(liststring))) + b's %d: %s'
+ # 4 to account for the word 'line'
+ spacing_len = max(4, 55 - len(liststring))
+ prefix = b''
+ if spacing_len == 4:
+ prefix = b', '
+
+ codepattern = b'%s%s %d: %s%s'
codestring = codepattern % (
- b'line',
+ prefix,
+ b'line'.rjust(spacing_len),
site.lineno,
+ b''.ljust(max(0, 4 - len(str(site.lineno)))),
site.getsource(30),
)
--- a/tests/test-profile.t Wed Dec 02 15:38:05 2020 -0800
+++ b/tests/test-profile.t Wed Dec 02 12:33:51 2020 -0800
@@ -64,19 +64,19 @@
Install an extension that can sleep and guarantee a profiler has time to run
- $ cat >> sleepext.py << EOF
+ $ cat >> sleepext_with_a_long_filename.py << EOF
> import time
> from mercurial import registrar
> cmdtable = {}
> command = registrar.command(cmdtable)
> @command(b'sleep', [], b'hg sleep')
- > def sleep(ui, *args, **kwargs):
+ > def sleep_for_at_least_one_stat_cycle(ui, *args, **kwargs):
> time.sleep(0.1)
> EOF
$ cat >> $HGRCPATH << EOF
> [extensions]
- > sleep = `pwd`/sleepext.py
+ > sleep = `pwd`/sleepext_with_a_long_filename.py
> EOF
statistical profiler works
@@ -90,7 +90,7 @@
$ grep -v _path_stat ../out | head -n 3
% cumulative self
time seconds seconds name
- * sleepext.py:*:sleep (glob)
+ * sleepext_with_a_long_filename.py:*:sleep_for_at_least_one_stat_cycle (glob)
$ cat ../out | statprofran
$ hg --profile --config profiling.statformat=bymethod sleep 2>../out || cat ../out
@@ -100,8 +100,8 @@
$ 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)
+ $ grep sleepext_with_a_long_filename.py ../out
+ .* [0-9.]+% [0-9.]+s sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line 7: time\.sleep.* (re)
$ hg --profile --config profiling.statformat=json sleep 2>../out || cat ../out
$ cat ../out