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

[Gregory Szorc]

> On Feb 13, 2017, at 10:29, Simon Farnsworth  wrote:
> 
> # HG changeset patch
> # User Simon Farnsworth 
> # 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
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

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

[Augie Fackler]

On Mon, Feb 13, 2017 at 09:29:02AM -0800, Simon Farnsworth wrote:
> # HG changeset patch
> # User Simon Farnsworth 
> # 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
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

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

[Simon Farnsworth]

On 13/02/2017 18:06, Bryan O'Sullivan wrote:


On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth > 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.

--
Simon Farnsworth
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

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

[Simon Farnsworth]

# HG changeset patch
# User Simon Farnsworth 
# 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
+
 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