Patchwork [1,of,6,v2] ui: provide a mechanism to track and log blocked time

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 9, 2017, 9:52 p.m.
Message ID <ec1dac3c0d5fc7d0d15a.1486677134@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18369/
State Changes Requested
Headers show

Comments

Simon Farnsworth - Feb. 9, 2017, 9:52 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# Date 1486675708 28800
#      Thu Feb 09 13:28:28 2017 -0800
# Node ID ec1dac3c0d5fc7d0d15af324b345958a41000960
# Parent  1f51b4658f21bbb797e922d155c1046eddccf91d
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
Bryan O'Sullivan - Feb. 10, 2017, 12:06 a.m.
On Thu, Feb 9, 2017 at 1:52 PM, Simon Farnsworth <simonfar@fb.com> wrote:

>
> diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
> --- a/mercurial/dispatch.py
> +++ b/mercurial/dispatch.py
> @@ -17,6 +17,7 @@
>  import signal
>  import sys
>  import time
> +import timeit
>  import traceback
>
>
> @@ -123,7 +124,7 @@
>          return -1
>
>      msg = ' '.join(' ' in a and repr(a) or a for a in req.args)
> -    starttime = time.time()
> +    starttime = timeit.default_timer()
>      ret = None
>      try:
>          ret = _runcatch(req)
> @@ -135,8 +136,11 @@
>                  raise
>          ret = -1
>      finally:
> -        duration = time.time() - starttime
> +        duration = timeit.default_timer() - starttime
>

(This is a good change, but should be in a separate patch...)

             self.httppasswordmgrdb = urlreq.httppasswordmgrwithdefaultreal
> m()
> +            self._blockedtimes = {}
>

self._blockedtimes = collections.defaultdict(lambda: 0)


> +        self._blockedtimes[key] = self._blockedtimes.get(key, 0) +
> duration
>

self._blockedtimes[key] += duration
Bryan O'Sullivan - Feb. 10, 2017, 12:44 a.m.
On Thu, Feb 9, 2017 at 1:52 PM, Simon Farnsworth <simonfar@fb.com> wrote:

> ui: provide a mechanism to track and log blocked time
>

I looked through the whole series, and it generally looks good.

Could you please add a contrib/perf.py benchmark to measure the performance
of ui.write with this new context manager based scheme, and include the
results in the commit message?

I like your context manager approach for the infrequent-use cases, but for
high-frequency users (mainly just ui.write), I'm going to be unable to
shake a nagging worry that this is still "too much overhead" until I can be
reassured otherwise by actual numbers :-)

Patch

diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -17,6 +17,7 @@ 
 import signal
 import sys
 import time
+import timeit
 import traceback
 
 
@@ -123,7 +124,7 @@ 
         return -1
 
     msg = ' '.join(' ' in a and repr(a) or a for a in req.args)
-    starttime = time.time()
+    starttime = timeit.default_timer()
     ret = None
     try:
         ret = _runcatch(req)
@@ -135,8 +136,11 @@ 
                 raise
         ret = -1
     finally:
-        duration = time.time() - starttime
+        duration = timeit.default_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
@@ -16,6 +16,7 @@ 
 import socket
 import sys
 import tempfile
+import timeit
 import traceback
 
 from .i18n import _
@@ -120,6 +121,8 @@ 
         self.callhooks = True
         # Insecure server connections requested.
         self.insecureconnections = False
+        # Blocked time
+        self.logblockedtimes = False
 
         if src:
             self.fout = src.fout
@@ -137,6 +140,7 @@ 
             self.fixconfig()
 
             self.httppasswordmgrdb = src.httppasswordmgrdb
+            self._blockedtimes = src._blockedtimes
         else:
             self.fout = util.stdout
             self.ferr = util.stderr
@@ -146,6 +150,7 @@ 
             self.environ = encoding.environ
 
             self.httppasswordmgrdb = urlreq.httppasswordmgrwithdefaultrealm()
+            self._blockedtimes = {}
 
         allowed = self.configlist('experimental', 'exportableenviron')
         if '*' in allowed:
@@ -174,6 +179,14 @@ 
             self._progbar.resetstate()  # reset last-print time of progress bar
         self.httppasswordmgrdb = urlreq.httppasswordmgrwithdefaultrealm()
 
+    @contextlib.contextmanager
+    def timeblockedsection(self, key):
+        starttime = timeit.default_timer()
+        yield
+        duration = (timeit.default_timer() - starttime) * 1000
+        key += '_blocked'
+        self._blockedtimes[key] = self._blockedtimes.get(key, 0) + duration
+
     def formatter(self, topic, opts):
         return formatter.formatter(self, topic, opts)
 
@@ -277,6 +290,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 stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
+  > [ui]
+  > logblockedtimes=True
+  > EOF
+
+  $ hg log
+  uiblocked stdio * ms command * ms (glob)