Patchwork [05,of,10,v5] ui: log time spent blocked on stdio

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 15, 2017, 10:06 p.m.
Message ID <1487dd34f44315371738.1487196415@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18518/
State Accepted
Headers show

Comments

Simon Farnsworth - Feb. 15, 2017, 10:06 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# Date 1487195406 28800
#      Wed Feb 15 13:50:06 2017 -0800
# Node ID 1487dd34f44315371738b13519cc4af1c81a7b07
# Parent  4d0b19ca8a56341fe2a77fd243232185ab4bf5e0
ui: log time spent blocked on stdio

We use a wrapper around Mercurial at Facebook that logs key statistics (like
elpased time) to our standard performance tooling.

This is less useful than it could be, because we currently can't tell when a
command is slow because we need to fix Mercurial versus when a command is
slow because the user isn't interacting quickly.

Teach Mercurial to log the time it spends blocked, so that our tooling can
pick it up and submit it with the elapsed time - we can then do the math in
our tooling to see if Mercurial is slow, or if the user simply failed to
interact.

Combining this with the command duration log means that we can ensure that
we concentrate performance efforts on the things that bite Facebook users.

The perfwrite microbenchmark shifts from:
Linux:
! wall 3.213560 comb 0.410000 user 0.350000 sys 0.060000 (best of 4)
Mac:
! wall 0.342325 comb 0.180000 user 0.110000 sys 0.070000 (best of 20)

before this change to:
! wall 3.478070 comb 0.500000 user 0.420000 sys 0.080000 (best of 3)
Mac:
! wall 0.218112 comb 0.220000 user 0.150000 sys 0.070000 (best of 15)

showing a small hit in comb time, but firmly in the noise on wall time.
Simon Farnsworth - Feb. 16, 2017, 8:30 a.m.
On 15/02/2017 22:06, Simon Farnsworth wrote:
> diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
> --- a/tests/test-logtoprocess.t
> +++ b/tests/test-logtoprocess.t
> @@ -61,10 +61,10 @@
>    > logtoprocess=
>    > pager=
>    > [logtoprocess]
> -  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
> +  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
>    > [ui]
>    > logblockedtimes=True
>    > EOF
>
>    $ hg log
> -  uiblocked command [0-9]+.[0-9]* ms (re)
> +  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)

This test works for me locally, but the new regex seems to fail on the 
buildbot: 
https://buildbot.mercurial-scm.org/builders/hg%20tests/builds/710/steps/run-tests.py%20(python%202.7.10)/logs/stdio

-  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
+  uiblocked stdio 0.0138282775879 ms command 31.3360691071 ms

Can anyone see what I've done wrong? The regex is supposed to remove the 
times, but clearly doesn't in some cases.
timeless - Feb. 20, 2017, 3:39 a.m.
Simon Farnsworth wrote:
>> -  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
>> +  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command
>> \$OPT_COMMAND_DURATION ms"

For reference, what you've missed was this part.
The part below was fine, but here, you can clearly see it changed from
`command` to stdio`.

had the diff used a smaller -U value, it would have accepted the second change.
This happens to me all the time. I've been meaning to teach the test
harness to be smarter  about differences :/

Patch

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -199,6 +199,7 @@ 
 
     @contextlib.contextmanager
     def timeblockedsection(self, key):
+        # this is open-coded below - search for timeblockedsection to find them
         starttime = util.timer()
         try:
             yield
@@ -776,31 +777,44 @@ 
             self._buffers[-1].extend(a for a in args)
         else:
             self._progclear()
-            for a in args:
-                self.fout.write(a)
+            # opencode timeblockedsection because this is a critical path
+            starttime = util.timer()
+            try:
+                for a in args:
+                    self.fout.write(a)
+            finally:
+                self._blockedtimes['stdio_blocked'] += \
+                    (util.timer() - starttime) * 1000
 
     def write_err(self, *args, **opts):
         self._progclear()
         try:
             if self._bufferstates and self._bufferstates[-1][0]:
                 return self.write(*args, **opts)
-            if not getattr(self.fout, 'closed', False):
-                self.fout.flush()
-            for a in args:
-                self.ferr.write(a)
-            # stderr may be buffered under win32 when redirected to files,
-            # including stdout.
-            if not getattr(self.ferr, 'closed', False):
-                self.ferr.flush()
+            with self.timeblockedsection('stdio'):
+                if not getattr(self.fout, 'closed', False):
+                    self.fout.flush()
+                for a in args:
+                    self.ferr.write(a)
+                # stderr may be buffered under win32 when redirected to files,
+                # including stdout.
+                if not getattr(self.ferr, 'closed', False):
+                    self.ferr.flush()
         except IOError as inst:
             if inst.errno not in (errno.EPIPE, errno.EIO, errno.EBADF):
                 raise
 
     def flush(self):
-        try: self.fout.flush()
-        except (IOError, ValueError): pass
-        try: self.ferr.flush()
-        except (IOError, ValueError): pass
+        # opencode timeblockedsection because this is a critical path
+        starttime = util.timer()
+        try:
+            try: self.fout.flush()
+            except (IOError, ValueError): pass
+            try: self.ferr.flush()
+            except (IOError, ValueError): pass
+        finally:
+            self._blockedtimes['stdio_blocked'] += \
+                (util.timer() - starttime) * 1000
 
     def _isatty(self, fh):
         if self.configbool('ui', 'nontty', False):
@@ -962,7 +976,8 @@ 
         sys.stdout = self.fout
         # prompt ' ' must exist; otherwise readline may delete entire line
         # - http://bugs.python.org/issue12833
-        line = raw_input(' ')
+        with self.timeblockedsection('stdio'):
+            line = raw_input(' ')
         sys.stdin = oldin
         sys.stdout = oldout
 
@@ -1042,13 +1057,14 @@ 
             self.write_err(self.label(prompt or _('password: '), 'ui.prompt'))
             # disable getpass() only if explicitly specified. it's still valid
             # to interact with tty even if fin is not a tty.
-            if self.configbool('ui', 'nontty'):
-                l = self.fin.readline()
-                if not l:
-                    raise EOFError
-                return l.rstrip('\n')
-            else:
-                return getpass.getpass('')
+            with self.timeblockedsection('stdio'):
+                if self.configbool('ui', 'nontty'):
+                    l = self.fin.readline()
+                    if not l:
+                        raise EOFError
+                    return l.rstrip('\n')
+                else:
+                    return getpass.getpass('')
         except EOFError:
             raise error.ResponseExpected()
     def status(self, *msg, **opts):
diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
--- a/tests/test-logtoprocess.t
+++ b/tests/test-logtoprocess.t
@@ -61,10 +61,10 @@ 
   > logtoprocess=
   > pager=
   > [logtoprocess]
-  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
+  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
   > [ui]
   > logblockedtimes=True
   > EOF
 
   $ hg log
-  uiblocked command [0-9]+.[0-9]* ms (re)
+  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)