This is an archive of the discontinued Mercurial Phabricator instance.

Differential D6477

profiling: show actual time spent in hotpath display
ClosedPublic

Authored by valentin.gatienbaron on Jun 5 2019, 1:10 PM.

Details

Reviewers
pulkit
Group Reviewers
hg-reviewers
Commits
rHG0ae593e791fb: profiling: show actual time spent in hotpath display
Summary

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.

Diff Detail

Repository
rHG Mercurial
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

pulkit added a subscriber: pulkit.Jun 5 2019, 3:45 PM

I find that if it's not displayed, I frequently end up estimating the
numbers by hand.

Mee too! I think we should enable this by default. What do you think?

valentin.gatienbaron added a comment.Jun 5 2019, 9:09 PM

Oh yeah, I didn't really consider the default. I clearly prefer "true", so I'll change it. Maybe it's not even worth having an option. I think the only advantage of not printing this column is to have 5 more columns available for the code excerpt at the end of lines.

valentin.gatienbaron retitled this revision from profiling: add an option to show actual time spent to profiling: show actual time spent in hotpath display.Jun 5 2019, 9:17 PM
valentin.gatienbaron updated this revision to Diff 15352.
pulkit accepted this revision.Jun 6 2019, 7:59 AM
Closed by commit rHG0ae593e791fb: profiling: show actual time spent in hotpath display (authored by valentin.gatienbaron). · Explain WhyJun 6 2019, 8:21 AM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

Diff 15354

mercurial/configitems.py

default=None, default=None,
) )
coreconfigitem('profiling', 'showmax', coreconfigitem('profiling', 'showmax',
default=0.999, default=0.999,
) )
coreconfigitem('profiling', 'showmin', coreconfigitem('profiling', 'showmin',
default=dynamicdefault, default=dynamicdefault,
) )
coreconfigitem('profiling', 'showtime',
default=True,
)
coreconfigitem('profiling', 'sort', coreconfigitem('profiling', 'sort',
default='inlinetime', default='inlinetime',
) )
coreconfigitem('profiling', 'statformat', coreconfigitem('profiling', 'statformat',
default='hotpath', default='hotpath',
) )
coreconfigitem('profiling', 'time-track', coreconfigitem('profiling', 'time-track',
default=dynamicdefault, default=dynamicdefault,

mercurial/help/config.txt

display. Values format is the same as ``showmin``. display. Values format is the same as ``showmin``.
Only used by the ``stat`` profiler. Only used by the ``stat`` profiler.
For the ``chrome`` format, default is ``0.999``. For the ``chrome`` format, default is ``0.999``.
The option is unused on other formats. 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`` ``progress``
------------ ------------
Mercurial commands can draw progress bars that are as informative as Mercurial commands can draw progress bars that are as informative as
possible. Some progress bars only offer indeterminate information, while others possible. Some progress bars only offer indeterminate information, while others
have a definite end point. have a definite end point.
``debug`` ``debug``

mercurial/profiling.py

if profformat == 'chrome': if profformat == 'chrome':
showmin = ui.configwith(fraction, 'profiling', 'showmin', 0.005) showmin = ui.configwith(fraction, 'profiling', 'showmin', 0.005)
showmax = ui.configwith(fraction, 'profiling', 'showmax') showmax = ui.configwith(fraction, 'profiling', 'showmax')
kwargs.update(minthreshold=showmin, maxthreshold=showmax) kwargs.update(minthreshold=showmin, maxthreshold=showmax)
elif profformat == 'hotpath': elif profformat == 'hotpath':
# inconsistent config: profiling.showmin # inconsistent config: profiling.showmin
limit = ui.configwith(fraction, 'profiling', 'showmin', 0.05) limit = ui.configwith(fraction, 'profiling', 'showmin', 0.05)
kwargs[r'limit'] = limit kwargs[r'limit'] = limit
showtime = ui.configbool('profiling', 'showtime')
kwargs[r'showtime'] = showtime
statprof.display(fp, data=data, format=displayformat, **kwargs) statprof.display(fp, data=data, format=displayformat, **kwargs)
class profile(object): class profile(object):
"""Start profiling. """Start profiling.
Profiling is active when the context manager is active. When the context Profiling is active when the context manager is active. When the context
manager exits, profiling results will be written to the configured output. manager exits, profiling results will be written to the configured output.

mercurial/statprof.py

if i < len(stack): if i < len(stack):
child.add(stack[i:], time) child.add(stack[i:], time)
root = HotNode(None) root = HotNode(None)
lasttime = data.samples[0].time lasttime = data.samples[0].time
for sample in data.samples: for sample in data.samples:
root.add(sample.stack[::-1], sample.time - lasttime) root.add(sample.stack[::-1], sample.time - lasttime)
lasttime = sample.time lasttime = sample.time
showtime = kwargs.get(r'showtime', True)
def _write(node, depth, multiple_siblings): def _write(node, depth, multiple_siblings):
site = node.site site = node.site
visiblechildren = [c for c in node.children.itervalues() visiblechildren = [c for c in node.children.itervalues()
if c.count >= (limit * root.count)] if c.count >= (limit * root.count)]
if site: if site:
indent = depth * 2 - 1 indent = depth * 2 - 1
filename = '' filename = ''
function = '' function = ''
if len(node.children) > 0: if len(node.children) > 0:
childsite = list(node.children.itervalues())[0].site childsite = list(node.children.itervalues())[0].site
filename = (childsite.filename() + ':').ljust(15) filename = (childsite.filename() + ':').ljust(15)
function = childsite.function function = childsite.function
# lots of string formatting # lots of string formatting
listpattern = ''.ljust(indent) +\ listpattern = ''.ljust(indent) +\
('\\' if multiple_siblings else '|') +\ ('\\' 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, liststring = listpattern % (node.count / root.count * 100,
filename, function) filename, function)
codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d: %s' codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d: %s'
codestring = codepattern % ('line', site.lineno, site.getsource(30)) codestring = codepattern % ('line', site.lineno, site.getsource(30))
finalstring = liststring + codestring finalstring = liststring + codestring
childrensamples = sum([c.count for c in node.children.itervalues()]) childrensamples = sum([c.count for c in node.children.itervalues()])
# Make frames that performed more than 10% of the operation red # Make frames that performed more than 10% of the operation red