Mercurial > hg
changeset 38798:d58958676b3c
extensions: add detailed loading information
This lets you track down what exactly is happening during extension loading,
and how long various steps took.
| author | Martijn Pieters <mj@zopatista.com> |
|---|---|
| date | Wed, 01 Aug 2018 16:06:53 +0200 |
| parents | 8751d1e2a7ff |
| children | 2002c193f2bc |
| files | mercurial/extensions.py mercurial/hg.py tests/test-bad-extension.t |
| diffstat | 3 files changed, 115 insertions(+), 34 deletions(-) [+] |
line wrap: on
line diff
--- a/mercurial/extensions.py Wed Aug 01 16:05:41 2018 +0200 +++ b/mercurial/extensions.py Wed Aug 01 16:06:53 2018 +0200 @@ -124,7 +124,7 @@ # note: this ui.debug happens before --debug is processed, # Use --config ui.debug=1 to see them. if ui.configbool('devel', 'debug.extensions'): - ui.debug('could not import %s (%s): trying %s\n' + ui.debug('debug.extensions: - could not import %s (%s): trying %s\n' % (failed, stringutil.forcebytestr(err), next)) if ui.debugflag: ui.traceback() @@ -166,7 +166,7 @@ _rejectunicode(t, o._table) _validatecmdtable(ui, getattr(mod, 'cmdtable', {})) -def load(ui, name, path): +def load(ui, name, path, log=lambda *a: None): if name.startswith('hgext.') or name.startswith('hgext/'): shortname = name[6:] else: @@ -175,8 +175,11 @@ return None if shortname in _extensions: return _extensions[shortname] + log(' - loading extension: %r\n', shortname) _extensions[shortname] = None - mod = _importext(name, path, bind(_reportimporterror, ui)) + with util.timedcm() as stats: + mod = _importext(name, path, bind(_reportimporterror, ui)) + log(' > %r extension loaded in %s\n', shortname, stats) # Before we do anything with the extension, check against minimum stated # compatibility. This gives extension authors a mechanism to have their @@ -187,12 +190,16 @@ ui.warn(_('(third party extension %s requires version %s or newer ' 'of Mercurial; disabling)\n') % (shortname, minver)) return + log(' - validating extension tables: %r\n', shortname) _validatetables(ui, mod) _extensions[shortname] = mod _order.append(shortname) - for fn in _aftercallbacks.get(shortname, []): - fn(loaded=True) + log(' - invoking registered callbacks: %r\n', shortname) + with util.timedcm() as stats: + for fn in _aftercallbacks.get(shortname, []): + fn(loaded=True) + log(' > callbacks completed in %s\n', stats) return mod def _runuisetup(name, ui): @@ -225,28 +232,41 @@ return True def loadall(ui, whitelist=None): + if ui.configbool('devel', 'debug.extensions'): + log = lambda msg, *values: ui.debug('debug.extensions: ', + msg % values, label='debug.extensions') + else: + log = lambda *a, **kw: None result = ui.configitems("extensions") if whitelist is not None: result = [(k, v) for (k, v) in result if k in whitelist] newindex = len(_order) - for (name, path) in result: - if path: - if path[0:1] == '!': - _disabledextensions[name] = path[1:] - continue - try: - load(ui, name, path) - except Exception as inst: - msg = stringutil.forcebytestr(inst) + log('loading %sextensions\n', 'additional ' if newindex else '') + log('- processing %d entries\n', len(result)) + with util.timedcm() as stats: + for (name, path) in result: if path: - ui.warn(_("*** failed to import extension %s from %s: %s\n") - % (name, path, msg)) - else: - ui.warn(_("*** failed to import extension %s: %s\n") - % (name, msg)) - if isinstance(inst, error.Hint) and inst.hint: - ui.warn(_("*** (%s)\n") % inst.hint) - ui.traceback() + if path[0:1] == '!': + if name not in _disabledextensions: + log(' - skipping disabled extension: %r\n', name) + _disabledextensions[name] = path[1:] + continue + try: + load(ui, name, path, log) + except Exception as inst: + msg = stringutil.forcebytestr(inst) + if path: + ui.warn(_("*** failed to import extension %s from %s: %s\n") + % (name, path, msg)) + else: + ui.warn(_("*** failed to import extension %s: %s\n") + % (name, msg)) + if isinstance(inst, error.Hint) and inst.hint: + ui.warn(_("*** (%s)\n") % inst.hint) + ui.traceback() + + log('> loaded %d extensions, total time %s\n', + len(_order) - newindex, stats) # list of (objname, loadermod, loadername) tuple: # - objname is the name of an object in extension module, # from which extra information is loaded @@ -258,29 +278,47 @@ earlyextraloaders = [ ('configtable', configitems, 'loadconfigtable'), ] + + log('- loading configtable attributes\n') _loadextra(ui, newindex, earlyextraloaders) broken = set() + log('- executing uisetup hooks\n') for name in _order[newindex:]: - if not _runuisetup(name, ui): - broken.add(name) + log(' - running uisetup for %r\n', name) + with util.timedcm() as stats: + if not _runuisetup(name, ui): + log(' - the %r extension uisetup failed\n', name) + broken.add(name) + log(' > uisetup for %r took %s\n', name, stats) + log('- executing extsetup hooks\n') for name in _order[newindex:]: if name in broken: continue - if not _runextsetup(name, ui): - broken.add(name) + log(' - running extsetup for %r\n', name) + with util.timedcm() as stats: + if not _runextsetup(name, ui): + log(' - the %r extension extsetup failed\n', name) + broken.add(name) + log(' > extsetup for %r took %s\n', name, stats) for name in broken: + log(' - disabling broken %r extension\n', name) _extensions[name] = None # Call aftercallbacks that were never met. - for shortname in _aftercallbacks: - if shortname in _extensions: - continue + log('- executing remaining aftercallbacks\n') + with util.timedcm() as stats: + for shortname in _aftercallbacks: + if shortname in _extensions: + continue - for fn in _aftercallbacks[shortname]: - fn(loaded=False) + for fn in _aftercallbacks[shortname]: + log(' - extension %r not loaded, notify callbacks\n', + shortname) + fn(loaded=False) + log('> remaining aftercallbacks completed in %s\n', stats) # loadall() is called multiple times and lingering _aftercallbacks # entries could result in double execution. See issue4646. @@ -304,6 +342,7 @@ # - loadermod is the module where loader is placed # - loadername is the name of the function, # which takes (ui, extensionname, extraobj) arguments + log('- loading extension registration objects\n') extraloaders = [ ('cmdtable', commands, 'loadcmdtable'), ('colortable', color, 'loadcolortable'), @@ -314,7 +353,10 @@ ('templatefunc', templatefuncs, 'loadfunction'), ('templatekeyword', templatekw, 'loadkeyword'), ] - _loadextra(ui, newindex, extraloaders) + with util.timedcm() as stats: + _loadextra(ui, newindex, extraloaders) + log('> extension registration object loading took %s\n', stats) + log('extension loading complete\n') def _loadextra(ui, newindex, extraloaders): for name in _order[newindex:]:
--- a/mercurial/hg.py Wed Aug 01 16:05:41 2018 +0200 +++ b/mercurial/hg.py Wed Aug 01 16:06:53 2018 +0200 @@ -9,6 +9,7 @@ from __future__ import absolute_import import errno +import functools import hashlib import os import shutil @@ -162,9 +163,16 @@ """return a repository object for the specified path""" obj = _peerlookup(path).instance(ui, path, create, intents=intents) ui = getattr(obj, "ui", ui) + if ui.configbool('devel', 'debug.extensions'): + log = functools.partial( + ui.debug, 'debug.extensions: ', label='debug.extensions') + else: + log = lambda *a, **kw: None for f in presetupfuncs or []: f(ui, obj) + log('- executing reposetup hooks\n') for name, module in extensions.extensions(ui): + log(' - running reposetup for %s\n' % (name,)) hook = getattr(module, 'reposetup', None) if hook: hook(ui, obj)
--- a/tests/test-bad-extension.t Wed Aug 01 16:05:41 2018 +0200 +++ b/tests/test-bad-extension.t Wed Aug 01 16:06:53 2018 +0200 @@ -77,18 +77,49 @@ $ (hg help help --traceback --debug --config devel.debug.extensions=yes 2>&1) \ > | grep -v '^ ' \ > | egrep 'extension..[^p]|^Exception|Traceback|ImportError|not import' + debug.extensions: loading extensions + debug.extensions: - processing 5 entries + debug.extensions: - loading extension: 'gpg' + debug.extensions: > 'gpg' extension loaded in * (glob) + debug.extensions: - validating extension tables: 'gpg' + debug.extensions: - invoking registered callbacks: 'gpg' + debug.extensions: > callbacks completed in * (glob) + debug.extensions: - loading extension: 'badext' *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow Traceback (most recent call last): Exception: bit bucket overflow - could not import hgext.badext2 (No module named *badext2): trying hgext3rd.badext2 (glob) + debug.extensions: - loading extension: 'baddocext' + debug.extensions: > 'baddocext' extension loaded in * (glob) + debug.extensions: - validating extension tables: 'baddocext' + debug.extensions: - invoking registered callbacks: 'baddocext' + debug.extensions: > callbacks completed in * (glob) + debug.extensions: - loading extension: 'badext2' + debug.extensions: - could not import hgext.badext2 (No module named badext2): trying hgext3rd.badext2 Traceback (most recent call last): ImportError: No module named *badext2 (glob) - could not import hgext3rd.badext2 (No module named *badext2): trying badext2 (glob) + debug.extensions: - could not import hgext3rd.badext2 (No module named badext2): trying badext2 Traceback (most recent call last): ImportError: No module named *badext2 (glob) *** failed to import extension badext2: No module named badext2 Traceback (most recent call last): ImportError: No module named badext2 + debug.extensions: > loaded 2 extensions, total time * (glob) + debug.extensions: - loading configtable attributes + debug.extensions: - executing uisetup hooks + debug.extensions: - running uisetup for 'gpg' + debug.extensions: > uisetup for 'gpg' took * (glob) + debug.extensions: - running uisetup for 'baddocext' + debug.extensions: > uisetup for 'baddocext' took * (glob) + debug.extensions: - executing extsetup hooks + debug.extensions: - running extsetup for 'gpg' + debug.extensions: > extsetup for 'gpg' took * (glob) + debug.extensions: - running extsetup for 'baddocext' + debug.extensions: > extsetup for 'baddocext' took * (glob) + debug.extensions: - executing remaining aftercallbacks + debug.extensions: > remaining aftercallbacks completed in * (glob) + debug.extensions: - loading extension registration objects + debug.extensions: > extension registration object loading took * (glob) + debug.extensions: extension loading complete confirm that there's no crash when an extension's documentation is bad