( )⚙ D4349 cleanup: make all uses of timedcm specify what they're timing

This is an archive of the discontinued Mercurial Phabricator instance.

Differential D4349

cleanup: make all uses of timedcm specify what they're timing
ClosedPublic

Authored by durin42 on Aug 21 2018, 5:40 PM.

Details

Reviewers
None
Group Reviewers
hg-reviewers
Commits
rHG331ab85e910b: cleanup: make all uses of timedcm specify what they're timing
Summary

It's not used in the timing itself, but it's valuable for the trace
events we emit.

Diff Detail

Repository
rHG Mercurial
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

durin42 created this revision.Aug 21 2018, 5:40 PM
Closed by commit rHG331ab85e910b: cleanup: make all uses of timedcm specify what they're timing (authored by durin42). · Explain WhyAug 24 2018, 1:15 PM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

PathPackages
Mmercurial/extensions.py (14 lines)
Mmercurial/util.py (2 lines)
Mtests/test-util.py (8 lines)

Diff 10499

mercurial/extensions.py

else: else:
shortname = name shortname = name
if shortname in _builtin: if shortname in _builtin:
return None return None
if shortname in _extensions: if shortname in _extensions:
return _extensions[shortname] return _extensions[shortname]
log(' - loading extension: %r\n', shortname) log(' - loading extension: %r\n', shortname)
_extensions[shortname] = None _extensions[shortname] = None
with util.timedcm() as stats: with util.timedcm('load extension %r', shortname) as stats:
mod = _importext(name, path, bind(_reportimporterror, ui)) mod = _importext(name, path, bind(_reportimporterror, ui))
log(' > %r extension loaded in %s\n', shortname, stats) log(' > %r extension loaded in %s\n', shortname, stats)
# Before we do anything with the extension, check against minimum stated # Before we do anything with the extension, check against minimum stated
# compatibility. This gives extension authors a mechanism to have their # compatibility. This gives extension authors a mechanism to have their
# extensions short circuit when loaded with a known incompatible version # extensions short circuit when loaded with a known incompatible version
# of Mercurial. # of Mercurial.
minver = getattr(mod, 'minimumhgversion', None) minver = getattr(mod, 'minimumhgversion', None)
if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2): if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
ui.warn(_('(third party extension %s requires version %s or newer ' ui.warn(_('(third party extension %s requires version %s or newer '
'of Mercurial; disabling)\n') % (shortname, minver)) 'of Mercurial; disabling)\n') % (shortname, minver))
return return
log(' - validating extension tables: %r\n', shortname) log(' - validating extension tables: %r\n', shortname)
_validatetables(ui, mod) _validatetables(ui, mod)
_extensions[shortname] = mod _extensions[shortname] = mod
_order.append(shortname) _order.append(shortname)
log(' - invoking registered callbacks: %r\n', shortname) log(' - invoking registered callbacks: %r\n', shortname)
with util.timedcm() as stats: with util.timedcm('callbacks extension %r', shortname) as stats:
for fn in _aftercallbacks.get(shortname, []): for fn in _aftercallbacks.get(shortname, []):
fn(loaded=True) fn(loaded=True)
log(' > callbacks completed in %s\n', stats) log(' > callbacks completed in %s\n', stats)
return mod return mod
def _runuisetup(name, ui): def _runuisetup(name, ui):
uisetup = getattr(_extensions[name], 'uisetup', None) uisetup = getattr(_extensions[name], 'uisetup', None)
if uisetup: if uisetup:
else: else:
log = lambda *a, **kw: None log = lambda *a, **kw: None
result = ui.configitems("extensions") result = ui.configitems("extensions")
if whitelist is not None: if whitelist is not None:
result = [(k, v) for (k, v) in result if k in whitelist] result = [(k, v) for (k, v) in result if k in whitelist]
newindex = len(_order) newindex = len(_order)
log('loading %sextensions\n', 'additional ' if newindex else '') log('loading %sextensions\n', 'additional ' if newindex else '')
log('- processing %d entries\n', len(result)) log('- processing %d entries\n', len(result))
with util.timedcm() as stats: with util.timedcm('load all extensions') as stats:
for (name, path) in result: for (name, path) in result:
if path: if path:
if path[0:1] == '!': if path[0:1] == '!':
if name not in _disabledextensions: if name not in _disabledextensions:
log(' - skipping disabled extension: %r\n', name) log(' - skipping disabled extension: %r\n', name)
_disabledextensions[name] = path[1:] _disabledextensions[name] = path[1:]
continue continue
try: try:
log('- loading configtable attributes\n') log('- loading configtable attributes\n')
_loadextra(ui, newindex, earlyextraloaders) _loadextra(ui, newindex, earlyextraloaders)
broken = set() broken = set()
log('- executing uisetup hooks\n') log('- executing uisetup hooks\n')
for name in _order[newindex:]: for name in _order[newindex:]:
log(' - running uisetup for %r\n', name) log(' - running uisetup for %r\n', name)
with util.timedcm() as stats: with util.timedcm('uisetup %r', name) as stats:
if not _runuisetup(name, ui): if not _runuisetup(name, ui):
log(' - the %r extension uisetup failed\n', name) log(' - the %r extension uisetup failed\n', name)
broken.add(name) broken.add(name)
log(' > uisetup for %r took %s\n', name, stats) log(' > uisetup for %r took %s\n', name, stats)
log('- executing extsetup hooks\n') log('- executing extsetup hooks\n')
for name in _order[newindex:]: for name in _order[newindex:]:
if name in broken: if name in broken:
continue continue
log(' - running extsetup for %r\n', name) log(' - running extsetup for %r\n', name)
with util.timedcm() as stats: with util.timedcm('extsetup %r', name) as stats:
if not _runextsetup(name, ui): if not _runextsetup(name, ui):
log(' - the %r extension extsetup failed\n', name) log(' - the %r extension extsetup failed\n', name)
broken.add(name) broken.add(name)
log(' > extsetup for %r took %s\n', name, stats) log(' > extsetup for %r took %s\n', name, stats)
for name in broken: for name in broken:
log(' - disabling broken %r extension\n', name) log(' - disabling broken %r extension\n', name)
_extensions[name] = None _extensions[name] = None
# Call aftercallbacks that were never met. # Call aftercallbacks that were never met.
log('- executing remaining aftercallbacks\n') log('- executing remaining aftercallbacks\n')
with util.timedcm() as stats: with util.timedcm('aftercallbacks') as stats:
for shortname in _aftercallbacks: for shortname in _aftercallbacks:
if shortname in _extensions: if shortname in _extensions:
continue continue
for fn in _aftercallbacks[shortname]: for fn in _aftercallbacks[shortname]:
log(' - extension %r not loaded, notify callbacks\n', log(' - extension %r not loaded, notify callbacks\n',
shortname) shortname)
fn(loaded=False) fn(loaded=False)
('colortable', color, 'loadcolortable'), ('colortable', color, 'loadcolortable'),
('filesetpredicate', fileset, 'loadpredicate'), ('filesetpredicate', fileset, 'loadpredicate'),
('internalmerge', filemerge, 'loadinternalmerge'), ('internalmerge', filemerge, 'loadinternalmerge'),
('revsetpredicate', revset, 'loadpredicate'), ('revsetpredicate', revset, 'loadpredicate'),
('templatefilter', templatefilters, 'loadfilter'), ('templatefilter', templatefilters, 'loadfilter'),
('templatefunc', templatefuncs, 'loadfunction'), ('templatefunc', templatefuncs, 'loadfunction'),
('templatekeyword', templatekw, 'loadkeyword'), ('templatekeyword', templatekw, 'loadkeyword'),
] ]
with util.timedcm() as stats: with util.timedcm('load registration objects') as stats:
_loadextra(ui, newindex, extraloaders) _loadextra(ui, newindex, extraloaders)
log('> extension registration object loading took %s\n', stats) log('> extension registration object loading took %s\n', stats)
log('extension loading complete\n') log('extension loading complete\n')
def _loadextra(ui, newindex, extraloaders): def _loadextra(ui, newindex, extraloaders):
for name in _order[newindex:]: for name in _order[newindex:]:
module = _extensions[name] module = _extensions[name]
if not module: if not module:

mercurial/util.py

the cost of a function, e.g. as follows: the cost of a function, e.g. as follows:
@util.timed @util.timed
def foo(a, b, c): def foo(a, b, c):
pass pass
''' '''
def wrapper(*args, **kwargs): def wrapper(*args, **kwargs):
with timedcm() as time_stats: with timedcm(pycompat.bytestr(func.__name__)) as time_stats:
result = func(*args, **kwargs) result = func(*args, **kwargs)
stderr = procutil.stderr stderr = procutil.stderr
stderr.write('%s%s: %s\n' % ( stderr.write('%s%s: %s\n' % (
' ' * time_stats.level * 2, pycompat.bytestr(func.__name__), ' ' * time_stats.level * 2, pycompat.bytestr(func.__name__),
time_stats)) time_stats))
return result return result
return wrapper return wrapper

tests/test-util.py

self.assertEqual(bytes(stats), b'<unknown>') self.assertEqual(bytes(stats), b'<unknown>')
stats.elapsed = 12.34 stats.elapsed = 12.34
self.assertEqual(str(stats), pycompat.sysstr(util.timecount(12.34))) self.assertEqual(str(stats), pycompat.sysstr(util.timecount(12.34)))
self.assertEqual(bytes(stats), util.timecount(12.34)) self.assertEqual(bytes(stats), util.timecount(12.34))
def testtimedcmcleanexit(self): def testtimedcmcleanexit(self):
# timestamps 1, 4, elapsed time of 4 - 1 = 3 # timestamps 1, 4, elapsed time of 4 - 1 = 3
with mocktimer([1, 3], _start_default): with mocktimer([1, 3], _start_default):
with util.timedcm() as stats: with util.timedcm('pass') as stats:
# actual context doesn't matter # actual context doesn't matter
pass pass
self.assertEqual(stats.start, 1) self.assertEqual(stats.start, 1)
self.assertEqual(stats.elapsed, 3) self.assertEqual(stats.elapsed, 3)
self.assertEqual(stats.level, 1) self.assertEqual(stats.level, 1)
def testtimedcmnested(self): def testtimedcmnested(self):
# timestamps 1, 3, 6, 10, elapsed times of 6 - 3 = 3 and 10 - 1 = 9 # timestamps 1, 3, 6, 10, elapsed times of 6 - 3 = 3 and 10 - 1 = 9
with mocktimer([1, 2, 3, 4], _start_default): with mocktimer([1, 2, 3, 4], _start_default):
with util.timedcm() as outer_stats: with util.timedcm('outer') as outer_stats:
with util.timedcm() as inner_stats: with util.timedcm('inner') as inner_stats:
# actual context doesn't matter # actual context doesn't matter
pass pass
self.assertEqual(outer_stats.start, 1) self.assertEqual(outer_stats.start, 1)
self.assertEqual(outer_stats.elapsed, 9) self.assertEqual(outer_stats.elapsed, 9)
self.assertEqual(outer_stats.level, 1) self.assertEqual(outer_stats.level, 1)
self.assertEqual(inner_stats.start, 3) self.assertEqual(inner_stats.start, 3)
self.assertEqual(inner_stats.elapsed, 3) self.assertEqual(inner_stats.elapsed, 3)
self.assertEqual(inner_stats.level, 2) self.assertEqual(inner_stats.level, 2)
def testtimedcmexception(self): def testtimedcmexception(self):
# timestamps 1, 4, elapsed time of 4 - 1 = 3 # timestamps 1, 4, elapsed time of 4 - 1 = 3
with mocktimer([1, 3], _start_default): with mocktimer([1, 3], _start_default):
try: try:
with util.timedcm() as stats: with util.timedcm('exceptional') as stats:
raise ValueError() raise ValueError()
except ValueError: except ValueError:
pass pass
self.assertEqual(stats.start, 1) self.assertEqual(stats.start, 1)
self.assertEqual(stats.elapsed, 3) self.assertEqual(stats.elapsed, 3)
self.assertEqual(stats.level, 1) self.assertEqual(stats.level, 1)