Patchwork [2,of,8,v4] ui: provide a mechanism to track and log blocked time

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 13, 2017, 5:29 p.m.
Message ID <00f01e9a24bc050ab5cb.1487006942@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18446/
State Changes Requested
Headers show

Comments

Simon Farnsworth - Feb. 13, 2017, 5:29 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# Date 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 00f01e9a24bc050ab5cbbfc5a8dc99e992e31d2b
# Parent  88b51cd7e8e3764af542c25d79a33f5cbda37ac6
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. 13, 2017, 6:06 p.m.
On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <simonfar@fb.com> wrote:

> +        duration = (util.timer() - starttime) * 1000
> +        key += '_blocked'
> +        self._blockedtimes[key] += duration
>

Could be a one-liner, which will have a tiny but positive impact on perf:

self._blockedtimes[key + '_blocked'] += (util.timer() - starttime) * 1000
Simon Farnsworth - Feb. 13, 2017, 6:27 p.m.
On 13/02/2017 18:06, Bryan O'Sullivan wrote:
>
> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <simonfar@fb.com
> <mailto:simonfar@fb.com>> wrote:
>
>     +        duration = (util.timer() - starttime) * 1000
>     +        key += '_blocked'
>     +        self._blockedtimes[key] += duration
>
>
> Could be a one-liner, which will have a tiny but positive impact on perf:
>
> self._blockedtimes[key + '_blocked'] += (util.timer() - starttime) * 1000

Will change for the next resend.
Augie Fackler - Feb. 13, 2017, 7:46 p.m.
On Mon, Feb 13, 2017 at 09:29:02AM -0800, Simon Farnsworth wrote:
> # HG changeset patch
> # User Simon Farnsworth <simonfar@fb.com>
> # Date 1486994849 28800
> #      Mon Feb 13 06:07:29 2017 -0800
> # Node ID 00f01e9a24bc050ab5cbbfc5a8dc99e992e31d2b
> # Parent  88b51cd7e8e3764af542c25d79a33f5cbda37ac6
> 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
>
> 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
> @@ -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 = collections.defaultdict(lambda: 0)

Nit: use collections.defaultdict(int) - it saves the lambda overhead every
time you create a new dict entry:

In [9]: timeit.timeit('[x[y] for y in range(100)]', setup='import collections ; x=collections.defaultdict(lambda: 0)')
Out[9]: 8.992634057998657

In [10]: timeit.timeit('[x[y] for y in range(100)]', setup='import collections ; x=collections.defaultdict(int)')
Out[10]: 8.20629596710205

(doesn't matter for smaller sizes - at range(10), the lambda is cheaper, but it flips to being better for int somewhere before 100)

>
>          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 = util.timer()
> +        yield
> +        duration = (util.timer() - starttime) * 1000
> +        key += '_blocked'
> +        self._blockedtimes[key] += 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 [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Gregory Szorc - Feb. 14, 2017, 12:11 a.m.
> On Feb 13, 2017, at 10:29, Simon Farnsworth <simonfar@fb.com> wrote:
> 
> # HG changeset patch
> # User Simon Farnsworth <simonfar@fb.com>
> # Date 1486994849 28800
> #      Mon Feb 13 06:07:29 2017 -0800
> # Node ID 00f01e9a24bc050ab5cbbfc5a8dc99e992e31d2b
> # Parent  88b51cd7e8e3764af542c25d79a33f5cbda37ac6
> 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
> 
> 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
> @@ -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 = collections.defaultdict(lambda: 0)
> 
>         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 = util.timer()
> +        yield
> +        duration = (util.timer() - starttime) * 1000
> +        key += '_blocked'
> +        self._blockedtimes[key] += duration
> +

If the code inside the activated context manager raises, then the code here after the "yield" won't get executed.

Typically, @contextmanager functions have the following structure to avoid this pitfall:

try:
    yield
finally:
    #cleanup

>     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 [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

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
@@ -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 = collections.defaultdict(lambda: 0)
 
         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 = util.timer()
+        yield
+        duration = (util.timer() - starttime) * 1000
+        key += '_blocked'
+        self._blockedtimes[key] += 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 [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)