Patchwork [4,of,6,v2] ui: log time spent blocked on the user

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 2, 2017, 7:18 p.m.
Message ID <a590327ef7a47e1390bc.1486063138@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18303/
State Accepted
Headers show

Comments

Simon Farnsworth - Feb. 2, 2017, 7:18 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# Date 1486063056 28800
#      Thu Feb 02 11:17:36 2017 -0800
# Node ID a590327ef7a47e1390bcef0eef686c40ffc4894d
# Parent  722c309600ed9596a02674b04cb2caa9a65e8918
ui: log time spent blocked on the user

We use a wrapper around Mercurial at Facebook that logs key statistics (like
elapsed 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.

Patch

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 atexit
 import contextlib
 import errno
 import getpass
@@ -125,6 +126,7 @@ 
             self.fout = src.fout
             self.ferr = src.ferr
             self.fin = src.fin
+            self.edit = src.edit
 
             self._tcfg = src._tcfg.copy()
             self._ucfg = src._ucfg.copy()
@@ -277,12 +279,41 @@ 
             self._reportuntrusted = self.debugflag or self.configbool("ui",
                 "report_untrusted", True)
             self.tracebackflag = self.configbool('ui', 'traceback', False)
-
+            self.logblockedtime = self.configbool('ui', 'logblockedtime', False)
+            self.wrapblockers()
         if section in (None, 'trusted'):
             # update trust information
             self._trustusers.update(self.configlist('trusted', 'users'))
             self._trustgroups.update(self.configlist('trusted', 'groups'))
 
+    def wrapblockers(self):
+        if util.safehasattr(self.fin, 'counttime'):
+            self.fin.counttime = self.logblockedtime
+            self.ferr.counttime = self.logblockedtime
+            self.fout.counttime = self.logblockedtime
+            self.edit.counttime = self.logblockedtime
+        elif self.logblockedtime:
+            self.fin = util.elapsedtimewrapper(self.fin)
+            self.ferr = util.elapsedtimewrapper(self.ferr)
+            self.fout = util.elapsedtimewrapper(self.fout)
+            self.edit = util.elapsedtimewrapper(self.edit)
+            @atexit.register
+            def logblockedtime():
+                if not self.fin.counttime:
+                    return
+                self.log("uiblocked",
+                         "stdout blocked for %0.1f ms", self.fout.elapsedms,
+                         stdout_blocked=self.fout.elapsedms)
+                self.log("uiblocked",
+                         "stderr blocked for %0.1f ms", self.ferr.elapsedms,
+                         stderr_blocked=self.ferr.elapsedms)
+                self.log("uiblocked",
+                         "stdin blocked for %0.1f ms", self.fin.elapsedms,
+                         stdin_blocked=self.fin.elapsedms)
+                self.log("uiblocked",
+                         "edit blocked for %0.1f ms", self.edit.elapsedms,
+                         edit_blocked=self.edit.elapsedms)
+
     def backupconfig(self, section, item):
         return (self._ocfg.backup(section, item),
                 self._tcfg.backup(section, item),
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,63 @@ 
   logtoprocess commandfinish output:
   logtoprocess foo output:
   spam
+
+Test that logtoprocess captures uiblocked if requested
+
+  $ cp $HGRCPATH.bak $HGRCPATH
+  $ cat >>$HGRCPATH << EOF
+  > [extensions]
+  > logtoprocess=
+  > [logtoprocess]
+  > uiblocked=echo "logtoprocess uiblocked \$MSG1 \
+  > stdin time: \$OPT_STDIN_BLOCKED \
+  > stdout time: \$OPT_STDOUT_BLOCKED \
+  > stderr time: \$OPT_STDERR_BLOCKED \
+  > edit time: \$OPT_EDIT_BLOCKED"
+  > EOF
+
+First, without any config we should not see times logged.
+
+  $ hg log -r . | head -n50 | sort
+  
+  changeset:   -1:000000000000
+  date:        Thu Jan 01 00:00:00 1970 +0000
+  tag:         tip
+  user:        
+
+With config in two different forms, we should see times logged.
+
+  $ hg log --config ui.logblockedtime=True -r . | head -n50 | sort
+  
+  changeset:   -1:000000000000
+  date:        Thu Jan 01 00:00:00 1970 +0000
+  logtoprocess uiblocked edit blocked for %0.1f ms stdin time:  stdout time:  stderr time:  edit time: * (glob)
+  logtoprocess uiblocked stderr blocked for %0.1f ms stdin time:  stdout time:  stderr time: * edit time:  (glob)
+  logtoprocess uiblocked stdin blocked for %0.1f ms stdin time: * stdout time:  stderr time:  edit time:  (glob)
+  logtoprocess uiblocked stdout blocked for %0.1f ms stdin time:  stdout time: * stderr time:  edit time:  (glob)
+  tag:         tip
+  user:        
+  $ cat >>$HGRCPATH << EOF
+  > [ui]
+  > logblockedtime=True
+  > EOF
+
+  $ hg log -r . | head -n50 | sort
+  
+  changeset:   -1:000000000000
+  date:        Thu Jan 01 00:00:00 1970 +0000
+  logtoprocess uiblocked edit blocked for %0.1f ms stdin time:  stdout time:  stderr time:  edit time: * (glob)
+  logtoprocess uiblocked stderr blocked for %0.1f ms stdin time:  stdout time:  stderr time: * edit time:  (glob)
+  logtoprocess uiblocked stdin blocked for %0.1f ms stdin time: * stdout time:  stderr time:  edit time:  (glob)
+  logtoprocess uiblocked stdout blocked for %0.1f ms stdin time:  stdout time: * stderr time:  edit time:  (glob)
+  tag:         tip
+  user:        
+
+If we override from the command line, we should not see times logged.
+
+  $ hg log --config ui.logblockedtime=False -r . | head -n50 | sort
+  
+  changeset:   -1:000000000000
+  date:        Thu Jan 01 00:00:00 1970 +0000
+  tag:         tip
+  user: