changeset 39509:3a86f7eb8b78

extensions: trace the total time of running all extsetup callbacks Differential Revision: https://phab.mercurial-scm.org/D4511
author Boris Feld <boris.feld@octobus.net>
date Thu, 06 Sep 2018 16:21:42 -0400
parents 1a2bfc4d756a
children 340170192874
files mercurial/extensions.py tests/test-bad-extension.t tests/test-extension-timing.t
diffstat 3 files changed, 14 insertions(+), 9 deletions(-) [+]
line wrap: on
line diff
--- 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)
--- 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
--- 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