comparison mercurial/extensions.py @ 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.

38797:8751d1e2a7ff

def _reportimporterror(ui, err, failed, next):
    # 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'
                 % (failed, stringutil.forcebytestr(err), next))
        if ui.debugflag:
            ui.traceback()

def _rejectunicode(name, xs):

        o = getattr(mod, t, None)
        if o:
            _rejectunicode(t, o._table)
    _validatecmdtable(ui, getattr(mod, 'cmdtable', {}))

def load(ui, name, path):
    if name.startswith('hgext.') or name.startswith('hgext/'):
        shortname = name[6:]
    else:
        shortname = name
    if shortname in _builtin:
        return None
    if shortname in _extensions:
        return _extensions[shortname]
    _extensions[shortname] = None
    mod = _importext(name, path, bind(_reportimporterror, ui))

    # Before we do anything with the extension, check against minimum stated
    # compatibility. This gives extension authors a mechanism to have their
    # extensions short circuit when loaded with a known incompatible version
    # of Mercurial.
    minver = getattr(mod, 'minimumhgversion', None)
    if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
        ui.warn(_('(third party extension %s requires version %s or newer '
                  'of Mercurial; disabling)\n') % (shortname, minver))
        return
    _validatetables(ui, mod)

    _extensions[shortname] = mod
    _order.append(shortname)
    for fn in _aftercallbacks.get(shortname, []):
        fn(loaded=True)
    return mod

def _runuisetup(name, ui):
    uisetup = getattr(_extensions[name], 'uisetup', None)
    if uisetup:

            ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg))
            return False
    return True

def loadall(ui, whitelist=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)
            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()
    # list of (objname, loadermod, loadername) tuple:
    # - objname is the name of an object in extension module,
    #   from which extra information is loaded
    # - loadermod is the module where loader is placed
    # - loadername is the name of the function,

    #
    # This one is for the list of item that must be run before running any setup
    earlyextraloaders = [
        ('configtable', configitems, 'loadconfigtable'),
    ]
    _loadextra(ui, newindex, earlyextraloaders)

    broken = set()
    for name in _order[newindex:]:
        if not _runuisetup(name, ui):
            broken.add(name)

    for name in _order[newindex:]:
        if name in broken:
            continue
        if not _runextsetup(name, ui):
            broken.add(name)

    for name in broken:
        _extensions[name] = None

    # Call aftercallbacks that were never met.
    for shortname in _aftercallbacks:
        if shortname in _extensions:
            continue

        for fn in _aftercallbacks[shortname]:
            fn(loaded=False)

    # loadall() is called multiple times and lingering _aftercallbacks
    # entries could result in double execution. See issue4646.
    _aftercallbacks.clear()

    # - objname is the name of an object in extension module,
    #   from which extra information is loaded
    # - loadermod is the module where loader is placed
    # - loadername is the name of the function,
    #   which takes (ui, extensionname, extraobj) arguments
    extraloaders = [
        ('cmdtable', commands, 'loadcmdtable'),
        ('colortable', color, 'loadcolortable'),
        ('filesetpredicate', fileset, 'loadpredicate'),
        ('internalmerge', filemerge, 'loadinternalmerge'),
        ('revsetpredicate', revset, 'loadpredicate'),
        ('templatefilter', templatefilters, 'loadfilter'),
        ('templatefunc', templatefuncs, 'loadfunction'),
        ('templatekeyword', templatekw, 'loadkeyword'),
    ]
    _loadextra(ui, newindex, extraloaders)

def _loadextra(ui, newindex, extraloaders):
    for name in _order[newindex:]:
        module = _extensions[name]
        if not module:

38798:d58958676b3c

def _reportimporterror(ui, err, failed, next):
    # 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('debug.extensions:     - could not import %s (%s): trying %s\n'
                 % (failed, stringutil.forcebytestr(err), next))
        if ui.debugflag:
            ui.traceback()

def _rejectunicode(name, xs):

        o = getattr(mod, t, None)
        if o:
            _rejectunicode(t, o._table)
    _validatecmdtable(ui, getattr(mod, 'cmdtable', {}))

def load(ui, name, path, log=lambda *a: None):
    if name.startswith('hgext.') or name.startswith('hgext/'):
        shortname = name[6:]
    else:
        shortname = name
    if shortname in _builtin:
        return None
    if shortname in _extensions:
        return _extensions[shortname]
    log('  - loading extension: %r\n', shortname)
    _extensions[shortname] = None
    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
    # extensions short circuit when loaded with a known incompatible version
    # of Mercurial.
    minver = getattr(mod, 'minimumhgversion', None)
    if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
        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)
    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):
    uisetup = getattr(_extensions[name], 'uisetup', None)
    if uisetup:

            ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg))
            return False
    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)
    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:
                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
    # - loadermod is the module where loader is placed
    # - loadername is the name of the function,

    #
    # This one is for the list of item that must be run before running any setup
    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:]:
        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
        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.
    log('- executing remaining aftercallbacks\n')
    with util.timedcm() as stats:
        for shortname in _aftercallbacks:
            if shortname in _extensions:
                continue

            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.
    _aftercallbacks.clear()

    # - objname is the name of an object in extension module,
    #   from which extra information is loaded
    # - 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'),
        ('filesetpredicate', fileset, 'loadpredicate'),
        ('internalmerge', filemerge, 'loadinternalmerge'),
        ('revsetpredicate', revset, 'loadpredicate'),
        ('templatefilter', templatefilters, 'loadfilter'),
        ('templatefunc', templatefuncs, 'loadfunction'),
        ('templatekeyword', templatekw, 'loadkeyword'),
    ]
    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:]:
        module = _extensions[name]
        if not module: