# HG changeset patch
# User Boris Feld <boris.feld@octobus.net>
# Date 1536265302 14400
# Node ID 3a86f7eb8b78bdd08d357d654eaf3db93d707b1c
# Parent  1a2bfc4d756a6865e67113ff01fe8d2b8fdd9767
extensions: trace the total time of running all extsetup callbacks

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

diff -r 1a2bfc4d756a -r 3a86f7eb8b78 mercurial/extensions.py
--- a/mercurial/extensions.py	Thu Sep 06 16:20:05 2018 -0400
+++ b/mercurial/extensions.py	Thu Sep 06 16:21:42 2018 -0400
@@ -295,15 +295,17 @@
     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)
diff -r 1a2bfc4d756a -r 3a86f7eb8b78 tests/test-bad-extension.t
--- a/tests/test-bad-extension.t	Thu Sep 06 16:20:05 2018 -0400
+++ b/tests/test-bad-extension.t	Thu Sep 06 16:21:42 2018 -0400
@@ -117,6 +117,7 @@
   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
diff -r 1a2bfc4d756a -r 3a86f7eb8b78 tests/test-extension-timing.t
--- a/tests/test-extension-timing.t	Thu Sep 06 16:20:05 2018 -0400
+++ b/tests/test-extension-timing.t	Thu Sep 06 16:21:42 2018 -0400
@@ -63,6 +63,7 @@
   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 @@
   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