Patchwork [03,of,10,v5] ui: provide a mechanism to track and log blocked time

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 15, 2017, 10:06 p.m.
Message ID <f3a219226ba0658f7280.1487196413@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18515/
State Accepted
Headers show

Comments

Simon Farnsworth - Feb. 15, 2017, 10:06 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# Date 1487193465 28800
#      Wed Feb 15 13:17:45 2017 -0800
# Node ID f3a219226ba0658f72801329d07c1ba516152b70
# Parent  1c71bddbe01e76c1c48b5479ff67d47645afd7b6
ui: provide a mechanism to track and log blocked time

We want to log the time Mercurial spends trapped in things outside
programmatic control. Provide a mechanism to give us both command runtime
and as many different sources of blocking as we deem useful.
Yuya Nishihara - Feb. 18, 2017, 10:12 a.m.
On Wed, 15 Feb 2017 14:06:53 -0800, Simon Farnsworth wrote:
> # HG changeset patch
> # User Simon Farnsworth <simonfar@fb.com>
> # Date 1487193465 28800
> #      Wed Feb 15 13:17:45 2017 -0800
> # Node ID f3a219226ba0658f72801329d07c1ba516152b70
> # Parent  1c71bddbe01e76c1c48b5479ff67d47645afd7b6
> ui: provide a mechanism to track and log blocked time

>      finally:
>          duration = util.timer() - starttime
>          req.ui.flush()
> +        if req.ui.logblockedtimes:
> +            req.ui._blockedtimes['command_duration'] = duration * 1000
> +            req.ui.log('uiblocked', 'ui blocked ms', **req.ui._blockedtimes)

[snip]

>              self._reportuntrusted = self.debugflag or self.configbool("ui",
>                  "report_untrusted", True)
>              self.tracebackflag = self.configbool('ui', 'traceback', False)
> +            self.logblockedtimes = self.configbool('ui', 'logblockedtimes')

Just curious. Why this config knob is needed only to suppress the output?
I thought this would stop tracking the blocked time at all.

Patch

diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -137,6 +137,9 @@ 
     finally:
         duration = util.timer() - starttime
         req.ui.flush()
+        if req.ui.logblockedtimes:
+            req.ui._blockedtimes['command_duration'] = duration * 1000
+            req.ui.log('uiblocked', 'ui blocked ms', **req.ui._blockedtimes)
         req.ui.log("commandfinish", "%s exited %s after %0.2f seconds\n",
                    msg, ret or 0, duration)
     return ret
diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -7,6 +7,7 @@ 
 
 from __future__ import absolute_import
 
+import collections
 import contextlib
 import errno
 import getpass
@@ -138,6 +139,8 @@ 
         self.callhooks = True
         # Insecure server connections requested.
         self.insecureconnections = False
+        # Blocked time
+        self.logblockedtimes = False
 
         if src:
             self.fout = src.fout
@@ -155,6 +158,7 @@ 
             self.fixconfig()
 
             self.httppasswordmgrdb = src.httppasswordmgrdb
+            self._blockedtimes = src._blockedtimes
         else:
             self.fout = util.stdout
             self.ferr = util.stderr
@@ -164,6 +168,7 @@ 
             self.environ = encoding.environ
 
             self.httppasswordmgrdb = httppasswordmgrdbproxy()
+            self._blockedtimes = collections.defaultdict(int)
 
         allowed = self.configlist('experimental', 'exportableenviron')
         if '*' in allowed:
@@ -192,6 +197,15 @@ 
             self._progbar.resetstate()  # reset last-print time of progress bar
         self.httppasswordmgrdb = httppasswordmgrdbproxy()
 
+    @contextlib.contextmanager
+    def timeblockedsection(self, key):
+        starttime = util.timer()
+        try:
+            yield
+        finally:
+            self._blockedtimes[key + '_blocked'] += \
+                (util.timer() - starttime) * 1000
+
     def formatter(self, topic, opts):
         return formatter.formatter(self, topic, opts)
 
@@ -295,6 +309,7 @@ 
             self._reportuntrusted = self.debugflag or self.configbool("ui",
                 "report_untrusted", True)
             self.tracebackflag = self.configbool('ui', 'traceback', False)
+            self.logblockedtimes = self.configbool('ui', 'logblockedtimes')
 
         if section in (None, 'trusted'):
             # update trust information
diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
--- a/tests/test-logtoprocess.t
+++ b/tests/test-logtoprocess.t
@@ -10,6 +10,7 @@ 
   > def foo(ui, repo):
   >     ui.log('foo', 'a message: %(bar)s\n', bar='spam')
   > EOF
+  $ cp $HGRCPATH $HGRCPATH.bak
   $ cat >> $HGRCPATH << EOF
   > [extensions]
   > logtoprocess=
@@ -52,3 +53,18 @@ 
   logtoprocess commandfinish output:
   logtoprocess foo output:
   spam
+
+Confirm that logging blocked time catches stdio properly:
+  $ cp $HGRCPATH.bak $HGRCPATH
+  $ cat >> $HGRCPATH << EOF
+  > [extensions]
+  > logtoprocess=
+  > pager=
+  > [logtoprocess]
+  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
+  > [ui]
+  > logblockedtimes=True
+  > EOF
+
+  $ hg log
+  uiblocked command [0-9]+.[0-9]* ms (re)