changeset 42439:0ae593e791fb

profiling: show actual time spent in hotpath display To get, for instance: ... \ 6.6% 4.08s lock.py: __exit__ line 1566: ... | 6.5% 4.01s exchange.py: close line 1191: ... | 6.5% 4.01s transaction.py: _active line 1443: ... | 6.5% 4.01s transaction.py: close line 47: ... | 6.2% 3.84s scmutil.py: wrapped line 529: ... | 6.2% 3.81s localrepo.py: wrapper line 2114: ... | 6.2% 3.81s localrepo.py: updatecaches line 177: ... ... instead of: ... \ 6.6% lock.py: __exit__ line 1566: ... | 6.5% exchange.py: close line 1191: ... | 6.5% transaction.py: _active line 1443: ... | 6.5% transaction.py: close line 47: ... | 6.2% scmutil.py: wrapped line 529: ... | 6.2% localrepo.py: wrapper line 2114: ... | 6.2% localrepo.py: updatecaches line 177: ... ... I find that if it's not displayed, I frequently end up estimating the numbers by hand. Differential Revision: https://phab.mercurial-scm.org/D6477
author Valentin Gatien-Baron <vgatien-baron@janestreet.com>
date Wed, 05 Jun 2019 12:51:21 -0400
parents 381d8fa53f34
children d3b5cbe311d9
files mercurial/configitems.py mercurial/help/config.txt mercurial/profiling.py mercurial/statprof.py
diffstat 4 files changed, 14 insertions(+), 1 deletions(-) [+]
line wrap: on
line diff
--- a/mercurial/configitems.py	Wed Jun 05 14:29:44 2019 -0700
+++ b/mercurial/configitems.py	Wed Jun 05 12:51:21 2019 -0400
@@ -947,6 +947,9 @@
 coreconfigitem('profiling', 'showmin',
     default=dynamicdefault,
 )
+coreconfigitem('profiling', 'showtime',
+    default=True,
+)
 coreconfigitem('profiling', 'sort',
     default='inlinetime',
 )
--- a/mercurial/help/config.txt	Wed Jun 05 14:29:44 2019 -0700
+++ b/mercurial/help/config.txt	Wed Jun 05 12:51:21 2019 -0400
@@ -1780,6 +1780,11 @@
 
     The option is unused on other formats.
 
+``showtime``
+    Show time taken as absolute durations, in addition to percentages.
+    Only used by the ``hotpath`` format.
+    (default: true)
+
 ``progress``
 ------------
 
--- a/mercurial/profiling.py	Wed Jun 05 14:29:44 2019 -0700
+++ b/mercurial/profiling.py	Wed Jun 05 12:51:21 2019 -0400
@@ -147,6 +147,8 @@
             # inconsistent config: profiling.showmin
             limit = ui.configwith(fraction, 'profiling', 'showmin', 0.05)
             kwargs[r'limit'] = limit
+            showtime = ui.configbool('profiling', 'showtime')
+            kwargs[r'showtime'] = showtime
 
         statprof.display(fp, data=data, format=displayformat, **kwargs)
 
--- a/mercurial/statprof.py	Wed Jun 05 14:29:44 2019 -0700
+++ b/mercurial/statprof.py	Wed Jun 05 12:51:21 2019 -0400
@@ -678,6 +678,7 @@
     for sample in data.samples:
         root.add(sample.stack[::-1], sample.time - lasttime)
         lasttime = sample.time
+    showtime = kwargs.get(r'showtime', True)
 
     def _write(node, depth, multiple_siblings):
         site = node.site
@@ -695,7 +696,9 @@
             # lots of string formatting
             listpattern = ''.ljust(indent) +\
                           ('\\' if multiple_siblings else '|') +\
-                          ' %4.1f%%  %s %s'
+                          ' %4.1f%%' +\
+                          (' %5.2fs' % node.count if showtime else '') +\
+                          '  %s %s'
             liststring = listpattern % (node.count / root.count * 100,
                                         filename, function)
             codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d:  %s'