This is an archive of the discontinued Mercurial Phabricator instance.

Differential D9511

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

Authored by spectral on Dec 2 2020, 10:20 PM.

Download Raw Diff

Details

Reviewers

pulkit

Group Reviewers

hg-reviewers

Commits

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

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.

If the stuff before "line ###" is long, there's no separation between the function name and the "line" string.
If the stuff before "line ###" is really long, there's excessive separation between the "line" string and the line number.
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:

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

spectral created this revision.Dec 2 2020, 10:20 PM

Herald added a reviewer: hg-reviewers. · View Herald TranscriptDec 2 2020, 10:20 PM

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

pulkit accepted this revision.Dec 3 2020, 3:20 AM

This revision is now accepted and ready to land.Dec 3 2020, 3:20 AM

spectral added a commit: rHG8b0a3ff5ed12: statprof: separate functions and "line", assume 4 digit line numbers.Dec 3 2020, 4:38 AM

Closed by commit rHG8b0a3ff5ed12: statprof: separate functions and "line", assume 4 digit line numbers (authored by spectral). · Explain Why

This revision was automatically updated to reflect the committed changes.

baymax updated this revision to Diff 24003.Dec 3 2020, 6:16 AM

Revision Contents
Changeset List

			Path	Packages
M			mercurial/statprof.py (12 lines)
M			tests/test-profile.t (12 lines)

Diff	ID	Description	Created	Lint	Unit
Base		Base
Diff 1	23981		Dec 2 2020, 10:20 PM	★	★
Diff 2	23995	rHG8b0a3ff5ed1278894f76e8c8f0a8777bdc7ccb4b	Dec 2 2020, 3:33 PM	★	★
Diff 3	24003		Dec 3 2020, 6:16 AM	★	★

Status	Author	Revision
Closed	spectral	D9511 statprof: separate functions and "line", assume 4 digit line numbers
Closed	spectral	D9510 statprof: fix off-by-one-line error in output
Closed	marmoute	D9513 phab-refresh: do not error out when the stack is empty
Closed	marmoute	D9507 run-tests: allow some slack about 'waiting on lock' message
Closed	marmoute	D9506 pull: flush stdin after the `pull from` message
Closed	marmoute	D9505 tests: explicitly skip the lock warning in some remotefilelog tests
Closed	marmoute	D9504 tests: use the right python when running dummyssh for narrow
Closed	spectral	D9503 copies: avoid materializing a full directory map during copy tracing
Closed	martinvonz	D9509 rebase: clear merge state when aborting in-memory merge on dirty working copy
Closed	martinvonz	D9508 tests: show that in-memory rebase leaves state when working copy is dirty

Diff 23995

mercurial/statprof.py

	+ (b' %5.2fs' % node.count if showtime else b'')			+ (b' %5.2fs' % node.count if showtime else b'')
	+ b' %s %s'			+ b' %s %s'
	)			)
	liststring = listpattern % (			liststring = listpattern % (
	node.count / root.count * 100,			node.count / root.count * 100,
	filename,			filename,
	function,			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 % (			codestring = codepattern % (
	b'line',			prefix,
				b'line'.rjust(spacing_len),
	site.lineno,			site.lineno,
				b''.ljust(max(0, 4 - len(str(site.lineno)))),
	site.getsource(30),			site.getsource(30),
	)			)

	finalstring = liststring + codestring			finalstring = liststring + codestring
	childrensamples = sum(			childrensamples = sum(
	[c.count for c in pycompat.itervalues(node.children)]			[c.count for c in pycompat.itervalues(node.children)]
	)			)
	# Make frames that performed more than 10% of the operation red			# Make frames that performed more than 10% of the operation red

tests/test-profile.t

	A single profile is logged because file logging doesn't append			A single profile is logged because file logging doesn't append
	$ grep CallCount ../profile.log \| wc -l			$ grep CallCount ../profile.log \| wc -l
	\s*1 (re)			\s*1 (re)

	#endif			#endif

	Install an extension that can sleep and guarantee a profiler has time to run			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			> import time
	> from mercurial import registrar			> from mercurial import registrar
	> cmdtable = {}			> cmdtable = {}
	> command = registrar.command(cmdtable)			> command = registrar.command(cmdtable)
	> @command(b'sleep', [], b'hg sleep')			> @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)			> time.sleep(0.1)
	> EOF			> EOF

	$ cat >> $HGRCPATH << EOF			$ cat >> $HGRCPATH << EOF
	> [extensions]			> [extensions]
	> sleep = `pwd`/sleepext.py			> sleep = `pwd`/sleepext_with_a_long_filename.py
	> EOF			> EOF

	statistical profiler works			statistical profiler works

	$ hg --profile sleep 2>../out			$ hg --profile sleep 2>../out
	$ cat ../out \| statprofran			$ cat ../out \| statprofran

	Various statprof formatters work			Various statprof formatters work

	$ hg --profile --config profiling.statformat=byline sleep 2>../out \|\| cat ../out			$ hg --profile --config profiling.statformat=byline sleep 2>../out \|\| cat ../out
	$ grep -v _path_stat ../out \| head -n 3			$ grep -v _path_stat ../out \| head -n 3
	% cumulative self			% cumulative self
	time seconds seconds name			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			$ cat ../out \| statprofran

	$ hg --profile --config profiling.statformat=bymethod sleep 2>../out \|\| cat ../out			$ hg --profile --config profiling.statformat=bymethod sleep 2>../out \|\| cat ../out
	$ head -n 1 ../out			$ head -n 1 ../out
	% cumulative self			% cumulative self
	$ cat ../out \| statprofran			$ cat ../out \| statprofran

	$ hg --profile --config profiling.statformat=hotpath sleep 2>../out \|\| cat ../out			$ hg --profile --config profiling.statformat=hotpath sleep 2>../out \|\| cat ../out
	$ cat ../out \| statprofran			$ cat ../out \| statprofran
	$ grep sleepext.py ../out			$ grep sleepext_with_a_long_filename.py ../out
	.* [0-9.]+% [0-9.]+s sleepext.py:\ssleep line 7: time\.sleep. (re)			.* [0-9.]+% [0-9.]+s sleepext_with_a_long_filename.py:\ssleep_for_at_least_one_stat_cycle, line 7: time\.sleep. (re)

	$ hg --profile --config profiling.statformat=json sleep 2>../out \|\| cat ../out			$ hg --profile --config profiling.statformat=json sleep 2>../out \|\| cat ../out
	$ cat ../out			$ cat ../out
	\[\[-?\d+.* (re)			\[\[-?\d+.* (re)

	statprof can be used as a standalone module			statprof can be used as a standalone module

	$ "$PYTHON" -m mercurial.statprof hotpath			$ "$PYTHON" -m mercurial.statprof hotpath