This is an archive of the discontinued Mercurial Phabricator instance.

Differential D4513

extension: add a summary of total loading time per extension
ClosedPublic

Authored by lothiraldan on Sep 8 2018, 6:07 AM.

Details

Reviewers
None
Group Reviewers
hg-reviewers
Commits
rHG1ab185c78cc3: extension: add a summary of total loading time per extension
rHG2f6fb9f0a191: extension: add a summary of total loading time per extension
Summary

Diff Detail

Repository
rHG Mercurial
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

lothiraldan created this revision.Sep 8 2018, 6:07 AM
Closed by commit rHG2f6fb9f0a191: extension: add a summary of total loading time per extension (authored by lothiraldan). · Explain WhySep 10 2018, 2:38 PM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

Diff 10847

mercurial/extensions.py

_rejectunicode(t, getattr(mod, t, {})) _rejectunicode(t, getattr(mod, t, {}))
for t in ['filesetpredicate', 'internalmerge', 'revsetpredicate', for t in ['filesetpredicate', 'internalmerge', 'revsetpredicate',
'templatefilter', 'templatefunc', 'templatekeyword']: 'templatefilter', 'templatefunc', 'templatekeyword']:
o = getattr(mod, t, None) o = getattr(mod, t, None)
if o: if o:
_rejectunicode(t, o._table) _rejectunicode(t, o._table)
_validatecmdtable(ui, getattr(mod, 'cmdtable', {})) _validatecmdtable(ui, getattr(mod, 'cmdtable', {}))
def load(ui, name, path, log=lambda *a: None): def load(ui, name, path, log=lambda *a: None, loadingtime=None):
if name.startswith('hgext.') or name.startswith('hgext/'): if name.startswith('hgext.') or name.startswith('hgext/'):
shortname = name[6:] shortname = name[6:]
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('load extension %r', shortname) 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)
if loadingtime is not None:
loadingtime[shortname] += stats.elapsed
# 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 '
return True return True
def loadall(ui, whitelist=None): def loadall(ui, whitelist=None):
if ui.configbool('devel', 'debug.extensions'): if ui.configbool('devel', 'debug.extensions'):
log = lambda msg, *values: ui.debug('debug.extensions: ', log = lambda msg, *values: ui.debug('debug.extensions: ',
msg % values, label='debug.extensions') msg % values, label='debug.extensions')
else: else:
log = lambda *a, **kw: None log = lambda *a, **kw: None
loadingtime = collections.defaultdict(int)
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('load all extensions') 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:
load(ui, name, path, log) load(ui, name, path, log, loadingtime)
except Exception as inst: except Exception as inst:
msg = stringutil.forcebytestr(inst) msg = stringutil.forcebytestr(inst)
if path: if path:
ui.warn(_("*** failed to import extension %s from %s: %s\n") ui.warn(_("*** failed to import extension %s from %s: %s\n")
% (name, path, msg)) % (name, path, msg))
else: else:
ui.warn(_("*** failed to import extension %s: %s\n") ui.warn(_("*** failed to import extension %s: %s\n")
% (name, msg)) % (name, msg))
with util.timedcm('all uisetup') as alluisetupstats: with util.timedcm('all uisetup') as alluisetupstats:
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('uisetup %r', name) 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)
loadingtime[name] += stats.elapsed
log('> all uisetup took %s\n', alluisetupstats) log('> all uisetup took %s\n', alluisetupstats)
log('- executing extsetup hooks\n') log('- executing extsetup hooks\n')
with util.timedcm('all extsetup') as allextetupstats: with util.timedcm('all extsetup') as allextetupstats:
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('extsetup %r', name) 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)
loadingtime[name] += stats.elapsed
log('> all extsetup took %s\n', allextetupstats) log('> all extsetup took %s\n', allextetupstats)
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')
('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('load registration objects') 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)
# Report per extension loading time (except reposetup)
for name in sorted(loadingtime):
extension_msg = '> extension %s take a total of %s to load\n'
log(extension_msg, name, util.timecount(loadingtime[name]))
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:
continue # loading this module failed continue # loading this module failed

tests/test-bad-extension.t

debug.extensions: > extsetup for 'gpg' took * (glob) debug.extensions: > extsetup for 'gpg' took * (glob)
debug.extensions: - running extsetup for 'baddocext' debug.extensions: - running extsetup for 'baddocext'
debug.extensions: > extsetup for 'baddocext' took * (glob) debug.extensions: > extsetup for 'baddocext' took * (glob)
debug.extensions: > all extsetup took * (glob) debug.extensions: > all extsetup took * (glob)
debug.extensions: - executing remaining aftercallbacks debug.extensions: - executing remaining aftercallbacks
debug.extensions: > remaining aftercallbacks completed in * (glob) debug.extensions: > remaining aftercallbacks completed in * (glob)
debug.extensions: - loading extension registration objects debug.extensions: - loading extension registration objects
debug.extensions: > extension registration object loading took * (glob) debug.extensions: > extension registration object loading took * (glob)
debug.extensions: > extension baddocext take a total of * to load (glob)
debug.extensions: > extension gpg take a total of * to load (glob)
debug.extensions: extension loading complete debug.extensions: extension loading complete
#endif #endif
confirm that there's no crash when an extension's documentation is bad confirm that there's no crash when an extension's documentation is bad
$ hg help --keyword baddocext $ hg help --keyword baddocext
*** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
*** failed to import extension badext2: No module named badext2 *** failed to import extension badext2: No module named badext2
Topics: Topics:
extensions Using Additional Features extensions Using Additional Features

tests/test-extension-timing.t

debug.extensions: - executing extsetup hooks debug.extensions: - executing extsetup hooks
debug.extensions: - running extsetup for 'foobar' debug.extensions: - running extsetup for 'foobar'
debug.extensions: > extsetup for 'foobar' took * (glob) debug.extensions: > extsetup for 'foobar' took * (glob)
debug.extensions: > all extsetup took * (glob) debug.extensions: > all extsetup took * (glob)
debug.extensions: - executing remaining aftercallbacks debug.extensions: - executing remaining aftercallbacks
debug.extensions: > remaining aftercallbacks completed in * (glob) debug.extensions: > remaining aftercallbacks completed in * (glob)
debug.extensions: - loading extension registration objects debug.extensions: - loading extension registration objects
debug.extensions: > extension registration object loading took * (glob) debug.extensions: > extension registration object loading took * (glob)
debug.extensions: > extension foobar take a total of * to load (glob)
debug.extensions: extension loading complete debug.extensions: extension loading complete
debug.extensions: loading additional extensions debug.extensions: loading additional extensions
debug.extensions: - processing 1 entries debug.extensions: - processing 1 entries
debug.extensions: > loaded 0 extensions, total time * (glob) debug.extensions: > loaded 0 extensions, total time * (glob)
debug.extensions: - loading configtable attributes debug.extensions: - loading configtable attributes
debug.extensions: - executing uisetup hooks debug.extensions: - executing uisetup hooks
debug.extensions: > all uisetup took * (glob) debug.extensions: > all uisetup took * (glob)
debug.extensions: - executing extsetup hooks debug.extensions: - executing extsetup hooks