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