[PATCH 2 of 2 v2] extensions: add detailed loading information
Martijn Pieters
mj at zopatista.com
Wed Aug 1 11:29:40 EDT 2018
# HG changeset patch
# User Martijn Pieters <mj at zopatista.com>
# Date 1533132413 -7200
# Wed Aug 01 16:06:53 2018 +0200
# Branch stable
# Node ID 07ca3b8354d59c70db5f10448e53d4bbfd50e72e
# Parent 2bad2ee57e26f05f99a81715e781f7978515b705
# EXP-Topic debugextensions
extensions: add detailed loading information
This lets you track down what exactly is happening during extension loading,
and how long various steps took.
diff -r 2bad2ee57e26 -r 07ca3b8354d5 mercurial/extensions.py
--- 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,46 @@
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 +341,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 +352,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:]:
diff -r 2bad2ee57e26 -r 07ca3b8354d5 mercurial/hg.py
--- 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)
diff -r 2bad2ee57e26 -r 07ca3b8354d5 tests/test-bad-extension.t
--- 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
More information about the Mercurial-devel
mailing list