##// END OF EJS Templates
statprof: separate functions and "line", assume 4 digit line numbers...
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

File last commit:

r46639:8b0a3ff5 default
r46639:8b0a3ff5 default
Show More
test-profile.t
169 lines | 4.3 KiB | text/troff | Tads3Lexer
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_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_for_at_least_one_stat_cycle(ui, *args, **kwargs):
> time.sleep(0.1)
> EOF
$ cat >> $HGRCPATH << EOF
> [extensions]
> sleep = `pwd`/sleepext_with_a_long_filename.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_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
$ 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_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
\[\[-?\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