# HG changeset patch # User Kyle Lippincott # Date 2020-12-02 20:33:51 # Node ID 8b0a3ff5ed1278894f76e8c8f0a8777bdc7ccb4b # Parent 068307b638f45e6bdab09b3030edb2cac2935b64 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: 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 : exec_moduleline 783: | 50.0% 0.01s : _call_with_frames_removedline 219: | 50.0% 0.01s changelog.py: line 376: class changelog(revlog.revl... | 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m... | 50.0% 0.01s : exec_moduleline 779: | 50.0% 0.01s : get_codeline 868: | 50.0% 0.01s : path_statsline 1012: | 50.0% 0.01s : _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: 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 : exec_module, line 783: | 50.0% 0.01s : _call_with_frames_removed, line 219: | 50.0% 0.01s changelog.py: line 376: class changelog(revlog.revl... | 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m... | 50.0% 0.01s : exec_module, line 779: | 50.0% 0.01s : get_code, line 868: | 50.0% 0.01s : path_stats, line 1012: | 50.0% 0.01s : _path_stat, line 87: ``` Differential Revision: https://phab.mercurial-scm.org/D9511 diff --git a/mercurial/statprof.py b/mercurial/statprof.py --- a/mercurial/statprof.py +++ b/mercurial/statprof.py @@ -768,10 +768,18 @@ def display_hotpath(data, fp, limit=0.05 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), ) diff --git a/tests/test-profile.t b/tests/test-profile.t --- a/tests/test-profile.t +++ b/tests/test-profile.t @@ -64,19 +64,19 @@ A single profile is logged because file 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 @@ Various statprof formatters work $ 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 @@ Various statprof formatters work $ 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