[PATCH 2 of 8 v4] ui: provide a mechanism to track and log blocked time
Augie Fackler
raf at durin42.com
Mon Feb 13 14:46:50 EST 2017
On Mon, Feb 13, 2017 at 09:29:02AM -0800, Simon Farnsworth wrote:
> # HG changeset patch
> # User Simon Farnsworth <simonfar at 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 at mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
More information about the Mercurial-devel
mailing list