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
#
# Copyright 2018 Google LLC.
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.
"""Tool read primitive events from a pipe to produce a catapult trace.
Usage:
Terminal 1: $ catapipe.py /tmp/mypipe /tmp/trace.json
Terminal 2: $ HGCATAPULTSERVERPIPE=/tmp/mypipe hg root
<ctrl-c catapipe.py in Terminal 1>
$ catapult/tracing/bin/trace2html /tmp/trace.json # produce /tmp/trace.html
<open trace.html in your browser of choice; the WASD keys are very useful>
(catapult is located at https://github.com/catapult-project/catapult)
For now the event stream supports
START $SESSIONID ...
and
END $SESSIONID ...
events. Everything after the SESSIONID (which must not contain spaces)
is used as a label for the event. Events are timestamped as of when
they arrive in this process and are then used to produce catapult
traces that can be loaded in Chrome's about:tracing utility. It's
important that the event stream *into* this process stay simple,
because we have to emit it from the shell scripts produced by
run-tests.py.
Typically you'll want to place the path to the named pipe in the
HGCATAPULTSERVERPIPE environment variable, which both run-tests and hg
understand. To trace *only* run-tests, use HGTESTCATAPULTSERVERPIPE instead.
"""
from __future__ import absolute_import, print_function
import argparse
import json
import os
import timeit
_TYPEMAP = {
'START': 'B',
'END': 'E',
'COUNTER': 'C',
}
_threadmap = {}
# Timeit already contains the whole logic about which timer to use based on
# Python version and OS
timer = timeit.default_timer
def main():
parser = argparse.ArgumentParser()
parser.add_argument(
'pipe',
type=str,
nargs=1,
help='Path of named pipe to create and listen on.',
)
parser.add_argument(
'output',
default='trace.json',
type=str,
nargs='?',
help='Path of json file to create where the traces ' 'will be stored.',
)
parser.add_argument(
'--debug',
default=False,
action='store_true',
help='Print useful debug messages',
)
args = parser.parse_args()
fn = args.pipe[0]
os.mkfifo(fn)
try:
with open(fn) as f, open(args.output, 'w') as out:
out.write('[\n')
start = timer()
while True:
ev = f.readline().strip()
if not ev:
continue
now = timer()
if args.debug:
print(ev)
verb, session, label = ev.split(' ', 2)
if session not in _threadmap:
_threadmap[session] = len(_threadmap)
if verb == 'COUNTER':
amount, label = label.split(' ', 1)
payload_args = {'value': int(amount)}
else:
payload_args = {}
pid = _threadmap[session]
ts_micros = (now - start) * 1000000
out.write(
json.dumps(
{
"name": label,
"cat": "misc",
"ph": _TYPEMAP[verb],
"ts": ts_micros,
"pid": pid,
"tid": 1,
"args": payload_args,
}
)
)
out.write(',\n')
finally:
os.unlink(fn)
if __name__ == '__main__':
main()