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.

Download Raw Diff

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

valentin.gatienbaron created this revision.Jun 5 2019, 1:10 PM

Herald added a reviewer: hg-reviewers. · View Herald TranscriptJun 5 2019, 1:10 PM

Herald added a subscriber: mercurial-devel. · View Herald Transcript

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?

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

			Path	Packages
M			mercurial/configitems.py (3 lines)
M			mercurial/help/config.txt (5 lines)
M			mercurial/profiling.py (2 lines)
M			mercurial/statprof.py (5 lines)

Diff	ID	Description	Created	Lint	Unit
Base		Base
Diff 1	15344		Jun 5 2019, 1:10 PM	★	★
Diff 2	15352		Jun 5 2019, 9:17 PM	★	★
Diff 3	15354	rHG0ae593e791fbfa8b08148be3d8033c1eec3b7dd4	Jun 5 2019, 12:51 PM	★	★

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