[PATCH 4 of 5] ui: log time spent blocked on the user

[Simon Farnsworth]

# HG changeset patch
# User Simon Farnsworth <simonfar at fb.com>
# Date 1484842917 28800
#      Thu Jan 19 08:21:57 2017 -0800
# Node ID 93221dde2fad942c4f920dab1f346da71ac8033d
# Parent  e8cd90ea5d3eee923304c64a19c3be9bce50451c
ui: log time spent blocked on the user

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.

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()
@@ -268,12 +270,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: