extensions: add timing for extensions reposetup

extensions: add timing for extensions reposetup

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

--- a/mercurial/hg.py	Fri Sep 07 11:18:45 2018 -0400
+++ b/mercurial/hg.py	Mon Sep 10 19:36:25 2018 -0700
@@ -9,7 +9,6 @@
 from __future__ import absolute_import
 
 import errno
-import functools
 import hashlib
 import os
 import shutil
@@ -164,8 +163,8 @@
     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')
+        log = lambda msg, *values: ui.debug('debug.extensions: ',
+            msg % values, label='debug.extensions')
     else:
         log = lambda *a, **kw: None
     for f in presetupfuncs or []:
@@ -175,7 +174,9 @@
         log('  - running reposetup for %s\n' % (name,))
         hook = getattr(module, 'reposetup', None)
         if hook:
-            hook(ui, obj)
+            with util.timedcm('reposetup %r', name) as stats:
+                hook(ui, obj)
+            log('  > reposetup for %r took %s\n', name, stats)
     if not obj.local():
         for f in wirepeersetupfuncs:
             f(ui, obj)

--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/tests/test-extension-timing.t	Mon Sep 10 19:36:25 2018 -0700
@@ -0,0 +1,90 @@
+Test basic extension support
+
+  $ cat > foobar.py <<EOF
+  > import os
+  > from mercurial import commands, registrar
+  > cmdtable = {}
+  > command = registrar.command(cmdtable)
+  > configtable = {}
+  > configitem = registrar.configitem(configtable)
+  > configitem(b'tests', b'foo', default=b"Foo")
+  > def uisetup(ui):
+  >     ui.debug(b"uisetup called [debug]\\n")
+  >     ui.write(b"uisetup called\\n")
+  >     ui.status(b"uisetup called [status]\\n")
+  >     ui.flush()
+  > def reposetup(ui, repo):
+  >     ui.write(b"reposetup called for %s\\n" % os.path.basename(repo.root))
+  >     ui.write(b"ui %s= repo.ui\\n" % (ui == repo.ui and b"=" or b"!"))
+  >     ui.flush()
+  > @command(b'foo', [], b'hg foo')
+  > def foo(ui, *args, **kwargs):
+  >     foo = ui.config(b'tests', b'foo')
+  >     ui.write(foo)
+  >     ui.write(b"\\n")
+  > @command(b'bar', [], b'hg bar', norepo=True)
+  > def bar(ui, *args, **kwargs):
+  >     ui.write(b"Bar\\n")
+  > EOF
+  $ abspath=`pwd`/foobar.py
+
+  $ mkdir barfoo
+  $ cp foobar.py barfoo/__init__.py
+  $ barfoopath=`pwd`/barfoo
+
+  $ hg init a
+  $ cd a
+  $ echo foo > file
+  $ hg add file
+  $ hg commit -m 'add file'
+
+  $ echo '[extensions]' >> $HGRCPATH
+  $ echo "foobar = $abspath" >> $HGRCPATH
+
+Test extension setup timings
+
+  $ hg foo --traceback --config devel.debug.extensions=yes --debug 2>&1
+  debug.extensions: loading extensions
+  debug.extensions: - processing 1 entries
+  debug.extensions:   - loading extension: 'foobar'
+  debug.extensions:   > 'foobar' extension loaded in * (glob)
+  debug.extensions:     - validating extension tables: 'foobar'
+  debug.extensions:     - invoking registered callbacks: 'foobar'
+  debug.extensions:     > callbacks completed in * (glob)
+  debug.extensions: > loaded 1 extensions, total time * (glob)
+  debug.extensions: - loading configtable attributes
+  debug.extensions: - executing uisetup hooks
+  debug.extensions:   - running uisetup for 'foobar'
+  uisetup called [debug]
+  uisetup called
+  uisetup called [status]
+  debug.extensions:   > uisetup for 'foobar' took * (glob)
+  debug.extensions: - executing extsetup hooks
+  debug.extensions:   - running extsetup for 'foobar'
+  debug.extensions:   > extsetup for 'foobar' 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
+  debug.extensions: loading additional extensions
+  debug.extensions: - processing 1 entries
+  debug.extensions: > loaded 0 extensions, total time * (glob)
+  debug.extensions: - loading configtable attributes
+  debug.extensions: - executing uisetup hooks
+  debug.extensions: - executing extsetup hooks
+  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
+  debug.extensions: - executing reposetup hooks
+  debug.extensions:   - running reposetup for foobar
+  reposetup called for a
+  ui == repo.ui
+  debug.extensions:   > reposetup for 'foobar' took * (glob)
+  Foo
+
+  $ cd ..
+
+  $ echo 'foobar = !' >> $HGRCPATH