Print time of long running hook actions

We can use this to evaluate the usefulness of making hooks run in parallel.

Review URL: https://chromiumcodereview.appspot.com/18851005

git-svn-id: svn://svn.chromium.org/chrome/trunk/tools/depot_tools@211446 0039d316-1c4b-4281-b951-d872f2087c98
diff --git a/gclient.py b/gclient.py
index d615402..ed08e47 100755
--- a/gclient.py
+++ b/gclient.py
@@ -81,6 +81,7 @@
 import pprint
 import re
 import sys
+import time
 import urllib
 import urlparse
 
@@ -780,6 +781,7 @@
     self._hooks_ran = True
     for hook in self.GetHooks(options):
       try:
+        start_time = time.time()
         gclient_utils.CheckCallAndFilterAndHeader(
             hook, cwd=self.root.root_dir, always=True)
       except (gclient_utils.Error, subprocess2.CalledProcessError), e:
@@ -788,6 +790,11 @@
         # differently from VC failures.
         print >> sys.stderr, 'Error: %s' % str(e)
         sys.exit(2)
+      finally:
+        elapsed_time = time.time() - start_time
+        if elapsed_time > 10:
+          print "Hook '%s' took %.2f secs" % (
+              gclient_utils.CommandToStr(hook), elapsed_time)
 
   def subtree(self, include_all):
     """Breadth first recursion excluding root node."""