Patchwork D9511: statprof: separate functions and "line", assume 4 digit line numbers

login
register
mail settings
Submitter phabricator
Date Dec. 3, 2020, 3:20 a.m.
Message ID <differential-rev-PHID-DREV-ekgurpx66uwr2aww4ww5-req@mercurial-scm.org>
Download mbox | patch
Permalink /patch/47793/
State Superseded
Headers show

Comments

phabricator - Dec. 3, 2020, 3:20 a.m.
spectral created this revision.
Herald added a reviewer: hg-reviewers.
Herald added a subscriber: mercurial-patches.

REVISION SUMMARY
  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:

REPOSITORY
  rHG Mercurial

BRANCH
  default

REVISION DETAIL
  https://phab.mercurial-scm.org/D9511

AFFECTED FILES
  mercurial/statprof.py
  tests/test-profile.t

CHANGE DETAILS




To: spectral, #hg-reviewers
Cc: mercurial-patches, mercurial-devel

Patch

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 @@ 
 
 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
diff --git a/mercurial/statprof.py b/mercurial/statprof.py
--- a/mercurial/statprof.py
+++ b/mercurial/statprof.py
@@ -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),
             )