[PATCH 3 of 6 V2] blackbox: logs python and extension hooks via ui.log()

[Durham Goode]

# HG changeset patch
# User Durham Goode <durham at fb.com>
# Date 1360429472 28800
#      Sat Feb 09 09:04:32 2013 -0800
# Node ID 0ad8fad9d10c58548d6472a0787dd53a5a681383
# Parent  61c66397b9a01d8e08333db6b220f882fe10c209
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\n'),
+            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\n'),
+        name, cmd, duration)
     if r:
         desc, r = util.explainexit(r)
         if throw: