extensions: trace the total time of running all uisetup callbacks
authorBoris Feld <boris.feld@octobus.net>
Thu, 06 Sep 2018 16:20:05 -0400
changeset 39525 1a2bfc4d756a
parent 39524 a5d6bf6032fb
child 39526 3a86f7eb8b78
extensions: trace the total time of running all uisetup callbacks Differential Revision: https://phab.mercurial-scm.org/D4510
mercurial/extensions.py
tests/test-bad-extension.t
tests/test-extension-timing.t
--- a/mercurial/extensions.py	Mon Sep 10 19:36:25 2018 -0700
+++ b/mercurial/extensions.py	Thu Sep 06 16:20:05 2018 -0400
@@ -284,13 +284,15 @@
 
     broken = set()
     log('- executing uisetup hooks\n')
-    for name in _order[newindex:]:
-        log('  - running uisetup for %r\n', name)
-        with util.timedcm('uisetup %r', name) as stats:
-            if not _runuisetup(name, ui):
-                log('    - the %r extension uisetup failed\n', name)
-                broken.add(name)
-        log('  > uisetup for %r took %s\n', name, stats)
+    with util.timedcm('all uisetup') as alluisetupstats:
+        for name in _order[newindex:]:
+            log('  - running uisetup for %r\n', name)
+            with util.timedcm('uisetup %r', name) as stats:
+                if not _runuisetup(name, ui):
+                    log('    - the %r extension uisetup failed\n', name)
+                    broken.add(name)
+            log('  > uisetup for %r took %s\n', name, stats)
+    log('> all uisetup took %s\n', alluisetupstats)
 
     log('- executing extsetup hooks\n')
     for name in _order[newindex:]:
--- a/tests/test-bad-extension.t	Mon Sep 10 19:36:25 2018 -0700
+++ b/tests/test-bad-extension.t	Thu Sep 06 16:20:05 2018 -0400
@@ -111,6 +111,7 @@
   debug.extensions:   > uisetup for 'gpg' took * (glob)
   debug.extensions:   - running uisetup for 'baddocext'
   debug.extensions:   > uisetup for 'baddocext' took * (glob)
+  debug.extensions: > all uisetup took * (glob)
   debug.extensions: - executing extsetup hooks
   debug.extensions:   - running extsetup for 'gpg'
   debug.extensions:   > extsetup for 'gpg' took * (glob)
--- a/tests/test-extension-timing.t	Mon Sep 10 19:36:25 2018 -0700
+++ b/tests/test-extension-timing.t	Thu Sep 06 16:20:05 2018 -0400
@@ -59,6 +59,7 @@
   uisetup called
   uisetup called [status]
   debug.extensions:   > uisetup for 'foobar' took * (glob)
+  debug.extensions: > all uisetup took * (glob)
   debug.extensions: - executing extsetup hooks
   debug.extensions:   - running extsetup for 'foobar'
   debug.extensions:   > extsetup for 'foobar' took * (glob)
@@ -72,6 +73,7 @@
   debug.extensions: > loaded 0 extensions, total time * (glob)
   debug.extensions: - loading configtable attributes
   debug.extensions: - executing uisetup hooks
+  debug.extensions: > all uisetup took * (glob)
   debug.extensions: - executing extsetup hooks
   debug.extensions: - executing remaining aftercallbacks
   debug.extensions: > remaining aftercallbacks completed in * (glob)