Wed, 02 Dec 2020 12:33:51 -0800 statprof: separate functions and "line", assume 4 digit line numbers
Kyle Lippincott <spectral@google.com> [Wed, 02 Dec 2020 12:33:51 -0800] rev 46033
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
Wed, 02 Dec 2020 15:38:05 -0800 statprof: fix off-by-one-line error in output
Kyle Lippincott <spectral@google.com> [Wed, 02 Dec 2020 15:38:05 -0800] rev 46032
statprof: fix off-by-one-line error in output martinvonz claims they thought that this was intentional, but couldn't remember the reasoning for it. I can't understand why it would be preferable, and I didn't see anything in the comments in the file about why this would be useful, so I'm hopefully not breaking anything by "fixing" it. ### Old output ``` | 100.0% 0.01s dispatch.py: run line 43: dispatch.run() | 100.0% 0.01s dispatch.py: dispatch line 115: status = dispatch(req) | 100.0% 0.01s dispatch.py: _runcatch line 266: ret = _runcatch(req) or 0 | 100.0% 0.01s dispatch.py: _callcatch line 442: return _callcatch(ui, _runc... | 100.0% 0.01s scmutil.py: callcatch line 451: return scmutil.callcatch(ui... | 100.0% 0.01s dispatch.py: _runcatchfunc line 155: return func() | 100.0% 0.01s dispatch.py: _dispatch line 432: return _dispatch(req) | 100.0% 0.01s hg.py: repository line 1179: repo = hg.repository( | 100.0% 0.01s hg.py: _peerorrepo line 221: peer = _peerorrepo( | 100.0% 0.01s util.py: __getattribute__ line 188: obj = _peerlookup(path).ins... | 100.0% 0.01s localrepo.py: makelocalrepositoryline 3227: return makelocalrepository(... | 100.0% 0.01s localrepo.py: __init__ line 683: return cls( | 100.0% 0.01s util.py: __getattribute__ line 1262: self._extrafilterid = repov... | 100.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 245: self.__spec__.loader.exec_m... | 100.0% 0.01s <frozen importlib._bootstrap_external>: get_codeline 779: | 100.0% 0.01s <frozen importlib._bootstrap_external>: path_statsline 868: | 100.0% 0.01s <frozen importlib._bootstrap_external>: _path_statline 1012: ``` ### New output ``` | 100.0% 0.01s hg: <module> line 43: dispatch.run() | 100.0% 0.01s dispatch.py: run line 115: status = dispatch(req) | 100.0% 0.01s dispatch.py: dispatch line 266: ret = _runcatch(req) or 0 | 100.0% 0.01s dispatch.py: _runcatch line 442: return _callcatch(ui, _runc... | 100.0% 0.01s dispatch.py: _callcatch line 451: return scmutil.callcatch(ui... | 100.0% 0.01s scmutil.py: callcatch line 155: return func() | 100.0% 0.01s dispatch.py: _runcatchfunc line 432: return _dispatch(req) | 100.0% 0.01s dispatch.py: _dispatch line 1179: repo = hg.repository( | 100.0% 0.01s hg.py: repository line 221: peer = _peerorrepo( | 100.0% 0.01s hg.py: _peerorrepo line 188: obj = _peerlookup(path).ins... | 100.0% 0.01s localrepo.py: instance line 3227: return makelocalrepository(... | 100.0% 0.01s localrepo.py: makelocalrepositoryline 683: return cls( | 100.0% 0.01s localrepo.py: __init__ line 1262: self._extrafilterid = repov... | 100.0% 0.01s util.py: __getattribute__ line 245: self.__spec__.loader.exec_m... | 100.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 779: | 100.0% 0.01s <frozen importlib._bootstrap_external>: get_codeline 868: | 100.0% 0.01s <frozen importlib._bootstrap_external>: path_statsline 1012: | 100.0% 0.01s <frozen importlib._bootstrap_external>: _path_statline 87: ``` Differential Revision: https://phab.mercurial-scm.org/D9510
(0) -30000 -10000 -3000 -1000 -300 -100 -30 -10 -2 +2 +10 +30 +100 +300 +1000 +3000 tip