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

mercurial/hook.py

@@ -6,7 +6,7 b''
 # 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 b' def _pythonhook(ui, repo, name, hname, f'
     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 b' def _pythonhook(ui, repo, name, hname, f'
             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 b' def _pythonhook(ui, repo, name, hname, f'
 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 b' def _exthook(ui, repo, name, cmd, args, '
         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: