--- 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)