extensions: trace the total time of running all extsetup callbacks

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

mercurial/extensions.py

@@ -295,15 +295,17 b' def loadall(ui, whitelist=None):'
     log('> all uisetup took %s\n', alluisetupstats)
 
     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('extsetup %r', name) 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)
+    with util.timedcm('all extsetup') as allextetupstats:
+        for name in _order[newindex:]:
+            if name in broken:
+                continue
+            log('  - running extsetup for %r\n', name)
+            with util.timedcm('extsetup %r', name) 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)
+    log('> all extsetup took %s\n', allextetupstats)
 
     for name in broken:
         log('    - disabling broken %r extension\n', name)

tests/test-bad-extension.t

@@ -117,6 +117,7 b' show traceback for ImportError of hgext.'
   debug.extensions:   > extsetup for 'gpg' took * (glob)
   debug.extensions:   - running extsetup for 'baddocext'
   debug.extensions:   > extsetup for 'baddocext' took * (glob)
+  debug.extensions: > all extsetup took * (glob)
   debug.extensions: - executing remaining aftercallbacks
   debug.extensions: > remaining aftercallbacks completed in * (glob)
   debug.extensions: - loading extension registration objects

tests/test-extension-timing.t

@@ -63,6 +63,7 b' Test extension setup timings'
   debug.extensions: - executing extsetup hooks
   debug.extensions:   - running extsetup for 'foobar'
   debug.extensions:   > extsetup for 'foobar' took * (glob)
+  debug.extensions: > all extsetup took * (glob)
   debug.extensions: - executing remaining aftercallbacks
   debug.extensions: > remaining aftercallbacks completed in * (glob)
   debug.extensions: - loading extension registration objects
@@ -75,6 +76,7 b' Test extension setup timings'
   debug.extensions: - executing uisetup hooks
   debug.extensions: > all uisetup took * (glob)
   debug.extensions: - executing extsetup hooks
+  debug.extensions: > all extsetup took * (glob)
   debug.extensions: - executing remaining aftercallbacks
   debug.extensions: > remaining aftercallbacks completed in * (glob)
   debug.extensions: - loading extension registration objects