From patchwork Sun Feb 10 11:07:19 2013
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: [3,of,6] blackbox: logs python and extension hooks via ui.log()
From: Durham Goode <durham@fb.com>
X-Patchwork-Id: 921
Message-Id: <eae69575df6cc5e429bf.1360494439@dev350.prn1.facebook.com>
To: mercurial-devel@selenic.com
Date: Sun, 10 Feb 2013 03:07:19 -0800

# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1360429472 28800
# Node ID eae69575df6cc5e429bfd6affbd957b6f3670fa4
# Parent  54a25c702a6fface978fd1eeb0e6c7140bc9ab8b
blackbox: logs python and extension hooks via ui.log()

Logs python and extension hooks to ui.log() for viewing in the blackbox.

Example log lines:
2013/02/09 08:35:19 durham> pythonhook-preupdate: hgext.eol.preupdate finished in 0.01 seconds
2013/02/09 08:35:19 durham> exthook-update: echo hooked finished in 0.02 seconds

diff --git a/mercurial/hook.py b/mercurial/hook.py
--- a/mercurial/hook.py
+++ b/mercurial/hook.py
@@ -6,7 +6,7 @@
 # GNU General Public License version 2 or any later version.
 
 from i18n import _
-import os, sys
+import os, sys, time, types
 import extensions, util, demandimport
 
 def _pythonhook(ui, repo, name, hname, funcname, args, throw):
@@ -20,6 +20,8 @@
     be run as hooks without wrappers to convert return values.'''
 
     ui.note(_("calling hook %s: %s\n") % (hname, funcname))
+    starttime = time.time()
+
     obj = funcname
     if not util.safehasattr(obj, '__call__'):
         d = funcname.rfind('.')
@@ -92,6 +94,12 @@
             return True
     finally:
         sys.stdout, sys.stderr, sys.stdin = old
+        duration = time.time() - starttime
+        readablefunc = funcname
+        if isinstance(funcname, types.FunctionType):
+            readablefunc = funcname.__module__ + "." + funcname.__name__
+        ui.log('pythonhook', 'pythonhook-%s: %s finished in %0.2f seconds' %
+            (name, readablefunc, duration))
     if r:
         if throw:
             raise util.Abort(_('%s hook failed') % hname)
@@ -101,6 +109,7 @@
 def _exthook(ui, repo, name, cmd, args, throw):
     ui.note(_("running hook %s: %s\n") % (name, cmd))
 
+    starttime = time.time()
     env = {}
     for k, v in args.iteritems():
         if util.safehasattr(v, '__call__'):
@@ -121,6 +130,10 @@
         r = util.system(cmd, environ=env, cwd=cwd, out=ui)
     else:
         r = util.system(cmd, environ=env, cwd=cwd, out=ui.fout)
+
+    duration = time.time() - starttime
+    ui.log('exthook', 'exthook-%s: %s finished in %0.2f seconds' %
+        (name, cmd, duration))
     if r:
         desc, r = util.explainexit(r)
         if throw: