exthelper: add some semi-useful trace logs

It'd be nice to make the trace functions a little better-named in the output,
but I'm not sure how much better we can do without overhead. This at least
lets you see if a single reposetup function is eating all the time or if it's
spread over all of them. I needed this because Google's uber-extension has a
long load time and I wasn't sure where the problem was.

Differential Revision: https://phab.mercurial-scm.org/D6381

mercurial/exthelper.py

@@ -1,300 +1,306 b''
 # Copyright 2012 Logilab SA        <[e-mail]>
 #                Pierre-Yves David <[e-mail]>
 #                Octobus <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 #####################################################################
 ### Extension helper                                              ###
 #####################################################################
 
 from __future__ import absolute_import
 
 from . import (
     commands,
     error,
     extensions,
+    pycompat,
     registrar,
 )
 
+from hgdemandimport import tracing
+
 class exthelper(object):
     """Helper for modular extension setup
 
     A single helper should be instantiated for each module of an
     extension, where a command or function needs to be wrapped, or a
     command, extension hook, fileset, revset or template needs to be
     registered.  Helper methods are then used as decorators for
     these various purposes.  If an extension spans multiple modules,
     all helper instances should be merged in the main module.
 
     All decorators return the original function and may be chained.
 
     Aside from the helper functions with examples below, several
     registrar method aliases are available for adding commands,
     configitems, filesets, revsets, and templates.  Simply decorate
     the appropriate methods, and assign the corresponding exthelper
     variable to a module level variable of the extension.  The
     extension loading mechanism will handle the rest.
 
     example::
 
         # ext.py
         eh = exthelper.exthelper()
 
         # As needed:
         cmdtable = eh.cmdtable
         configtable = eh.configtable
         filesetpredicate = eh.filesetpredicate
         revsetpredicate = eh.revsetpredicate
         templatekeyword = eh.templatekeyword
 
         @eh.command('mynewcommand',
             [('r', 'rev', [], _('operate on these revisions'))],
             _('-r REV...'),
             helpcategory=command.CATEGORY_XXX)
         def newcommand(ui, repo, *revs, **opts):
             # implementation goes here
 
         eh.configitem('experimental', 'foo',
             default=False,
         )
 
         @eh.filesetpredicate('lfs()')
         def filesetbabar(mctx, x):
             return mctx.predicate(...)
 
         @eh.revsetpredicate('hidden')
         def revsetbabar(repo, subset, x):
             args = revset.getargs(x, 0, 0, 'babar accept no argument')
             return [r for r in subset if 'babar' in repo[r].description()]
 
         @eh.templatekeyword('babar')
         def kwbabar(ctx):
             return 'babar'
     """
 
     def __init__(self):
         self._uipopulatecallables = []
         self._uicallables = []
         self._extcallables = []
         self._repocallables = []
         self._commandwrappers = []
         self._extcommandwrappers = []
         self._functionwrappers = []
         self.cmdtable = {}
         self.command = registrar.command(self.cmdtable)
         self.configtable = {}
         self.configitem = registrar.configitem(self.configtable)
         self.filesetpredicate = registrar.filesetpredicate()
         self.revsetpredicate = registrar.revsetpredicate()
         self.templatekeyword = registrar.templatekeyword()
 
     def merge(self, other):
         self._uicallables.extend(other._uicallables)
         self._uipopulatecallables.extend(other._uipopulatecallables)
         self._extcallables.extend(other._extcallables)
         self._repocallables.extend(other._repocallables)
         self.filesetpredicate._merge(other.filesetpredicate)
         self.revsetpredicate._merge(other.revsetpredicate)
         self.templatekeyword._merge(other.templatekeyword)
         self._commandwrappers.extend(other._commandwrappers)
         self._extcommandwrappers.extend(other._extcommandwrappers)
         self._functionwrappers.extend(other._functionwrappers)
         self.cmdtable.update(other.cmdtable)
         for section, items in other.configtable.iteritems():
             if section in self.configtable:
                 self.configtable[section].update(items)
             else:
                 self.configtable[section] = items
 
     def finaluisetup(self, ui):
         """Method to be used as the extension uisetup
 
         The following operations belong here:
 
         - Changes to ui.__class__ . The ui object that will be used to run the
           command has not yet been created. Changes made here will affect ui
           objects created after this, and in particular the ui that will be
           passed to runcommand
         - Command wraps (extensions.wrapcommand)
         - Changes that need to be visible to other extensions: because
           initialization occurs in phases (all extensions run uisetup, then all
           run extsetup), a change made here will be visible to other extensions
           during extsetup
         - Monkeypatch or wrap function (extensions.wrapfunction) of dispatch
           module members
         - Setup of pre-* and post-* hooks
         - pushkey setup
         """
         for command, wrapper, opts in self._commandwrappers:
             entry = extensions.wrapcommand(commands.table, command, wrapper)
             if opts:
                 for opt in opts:
                     entry[1].append(opt)
         for cont, funcname, wrapper in self._functionwrappers:
             extensions.wrapfunction(cont, funcname, wrapper)
         for c in self._uicallables:
+            with tracing.log(b'finaluisetup: %s', pycompat.sysbytes(repr(c))):
             c(ui)
 
     def finaluipopulate(self, ui):
         """Method to be used as the extension uipopulate
 
         This is called once per ui instance to:
 
         - Set up additional ui members
         - Update configuration by ``ui.setconfig()``
         - Extend the class dynamically
         """
         for c in self._uipopulatecallables:
             c(ui)
 
     def finalextsetup(self, ui):
         """Method to be used as a the extension extsetup
 
         The following operations belong here:
 
         - Changes depending on the status of other extensions. (if
           extensions.find('mq'))
         - Add a global option to all commands
         """
         knownexts = {}
 
         for ext, command, wrapper, opts in self._extcommandwrappers:
             if ext not in knownexts:
                 try:
                     e = extensions.find(ext)
                 except KeyError:
                     # Extension isn't enabled, so don't bother trying to wrap
                     # it.
                     continue
                 knownexts[ext] = e.cmdtable
             entry = extensions.wrapcommand(knownexts[ext], command, wrapper)
             if opts:
                 for opt in opts:
                     entry[1].append(opt)
 
         for c in self._extcallables:
+            with tracing.log(b'finalextsetup: %s', pycompat.sysbytes(repr(c))):
             c(ui)
 
     def finalreposetup(self, ui, repo):
         """Method to be used as the extension reposetup
 
         The following operations belong here:
 
         - All hooks but pre-* and post-*
         - Modify configuration variables
         - Changes to repo.__class__, repo.dirstate.__class__
         """
         for c in self._repocallables:
+            with tracing.log(b'finalreposetup: %s', pycompat.sysbytes(repr(c))):
             c(ui, repo)
 
     def uisetup(self, call):
         """Decorated function will be executed during uisetup
 
         example::
 
             @eh.uisetup
             def setupbabar(ui):
                 print 'this is uisetup!'
         """
         self._uicallables.append(call)
         return call
 
     def uipopulate(self, call):
         """Decorated function will be executed during uipopulate
 
         example::
 
             @eh.uipopulate
             def setupfoo(ui):
                 print 'this is uipopulate!'
         """
         self._uipopulatecallables.append(call)
         return call
 
     def extsetup(self, call):
         """Decorated function will be executed during extsetup
 
         example::
 
             @eh.extsetup
             def setupcelestine(ui):
                 print 'this is extsetup!'
         """
         self._extcallables.append(call)
         return call
 
     def reposetup(self, call):
         """Decorated function will be executed during reposetup
 
         example::
 
             @eh.reposetup
             def setupzephir(ui, repo):
                 print 'this is reposetup!'
         """
         self._repocallables.append(call)
         return call
 
     def wrapcommand(self, command, extension=None, opts=None):
         """Decorated function is a command wrapper
 
         The name of the command must be given as the decorator argument.
         The wrapping is installed during `uisetup`.
 
         If the second option `extension` argument is provided, the wrapping
         will be applied in the extension commandtable. This argument must be a
         string that will be searched using `extension.find` if not found and
         Abort error is raised. If the wrapping applies to an extension, it is
         installed during `extsetup`.
 
         example::
 
             @eh.wrapcommand('summary')
             def wrapsummary(orig, ui, repo, *args, **kwargs):
                 ui.note('Barry!')
                 return orig(ui, repo, *args, **kwargs)
 
         The `opts` argument allows specifying a list of tuples for additional
         arguments for the command.  See ``mercurial.fancyopts.fancyopts()`` for
         the format of the tuple.
 
         """
         if opts is None:
             opts = []
         else:
             for opt in opts:
                 if not isinstance(opt, tuple):
                     raise error.ProgrammingError('opts must be list of tuples')
                 if len(opt) not in (4, 5):
                     msg = 'each opt tuple must contain 4 or 5 values'
                     raise error.ProgrammingError(msg)
 
         def dec(wrapper):
             if extension is None:
                 self._commandwrappers.append((command, wrapper, opts))
             else:
                 self._extcommandwrappers.append((extension, command, wrapper,
                                                  opts))
             return wrapper
         return dec
 
     def wrapfunction(self, container, funcname):
         """Decorated function is a function wrapper
 
         This function takes two arguments, the container and the name of the
         function to wrap. The wrapping is performed during `uisetup`.
         (there is no extension support)
 
         example::
 
             @eh.function(discovery, 'checkheads')
             def wrapfunction(orig, *args, **kwargs):
                 ui.note('His head smashed in and his heart cut out')
                 return orig(*args, **kwargs)
         """
         def dec(wrapper):
             self._functionwrappers.append((container, funcname, wrapper))
             return wrapper
         return dec