# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1360429472 28800
# Node ID 1c305128e5b97fe4edb89a865c3e4581b6807a0c
# Parent  ddc7268da17692fbdedc851ce2c7ca1778543f97
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 -r ddc7268da176 -r 1c305128e5b9 mercurial/hook.py
--- a/mercurial/hook.py	Sat Feb 09 09:04:14 2013 -0800
+++ b/mercurial/hook.py	Sat Feb 09 09:04:32 2013 -0800
@@ -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: