Patchwork [2,of,2,v2] extensions: add detailed loading information

login
register
mail settings
Submitter Martijn Pieters
Date Aug. 1, 2018, 3:29 p.m.
Message ID <07ca3b8354d59c70db5f.1533137380@Martijns-MacBook-Pro.local>
Download mbox | patch
Permalink /patch/32999/
State Accepted
Headers show

Comments

Martijn Pieters - Aug. 1, 2018, 3:29 p.m.
# HG changeset patch
# User Martijn Pieters <mj@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.
Augie Fackler - Aug. 1, 2018, 8:12 p.m.
On Wed, Aug 01, 2018 at 05:29:40PM +0200, Martijn Pieters wrote:
> # HG changeset patch
> # User Martijn Pieters <mj@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

very interested in this, maybe CC me on the real v2?

>
> 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
>
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Yuya Nishihara - Aug. 2, 2018, 12:03 p.m.
On Wed, 01 Aug 2018 17:29:40 +0200, Martijn Pieters wrote:
> # HG changeset patch
> # User Martijn Pieters <mj@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

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

Seems like we're reinventing ui.log(). Can't this be a blackbox feature?

Patch

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