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

gclient.py

@@ -81,6 +81,7 @@ import posixpath
 import pprint
 import re
 import sys
+import time
 import urllib
 import urlparse
 
@@ -780,6 +781,7 @@ class Dependency(gclient_utils.WorkItem, DependencySettings):
     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 @@ class Dependency(gclient_utils.WorkItem, DependencySettings):
         # 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."""

gclient_utils.py

@@ -7,6 +7,7 @@
 import codecs
 import logging
 import os
+import pipes
 import Queue
 import re
 import stat
@@ -182,6 +183,11 @@ def safe_makedirs(tree):
         raise
 
 
+def CommandToStr(args):
+  """Converts an arg list into a shell escaped string."""
+  return ' '.join(pipes.quote(arg) for arg in args)
+
+
 def CheckCallAndFilterAndHeader(args, always=False, header=None, **kwargs):
   """Adds 'header' support to CheckCallAndFilter.
 
@@ -192,7 +198,7 @@ def CheckCallAndFilterAndHeader(args, always=False, header=None, **kwargs):
   stdout = kwargs.setdefault('stdout', sys.stdout)
   if header is None:
     header = "\n________ running '%s' in '%s'\n" % (
-                 ' '.join(args), kwargs.get('cwd', '.'))
+                 CommandToStr(args), kwargs.get('cwd', '.'))
 
   if always:
     stdout.write(header)

tests/gclient_utils_test.py

@@ -28,7 +28,7 @@ class GclientUtilsUnittest(GclientUtilBase):
   """General gclient_utils.py tests."""
   def testMembersChanged(self):
     members = [
-        'Annotated', 'AutoFlush', 'CheckCallAndFilter',
+        'Annotated', 'AutoFlush', 'CheckCallAndFilter', 'CommandToStr',
         'CheckCallAndFilterAndHeader', 'Error', 'ExecutionQueue', 'FileRead',
         'FileWrite', 'FindFileUpwards', 'FindGclientRoot',
         'GetGClientRootAndEntries', 'GetEditor', 'IsDateRevision',
@@ -37,9 +37,9 @@ class GclientUtilsUnittest(GclientUtilBase):
         'PrintableObject', 'RunEditor', 'GCLIENT_CHILDREN',
         'GCLIENT_CHILDREN_LOCK', 'GClientChildren',
         'SplitUrlRevision', 'SyntaxErrorToError', 'UpgradeToHttps', 'Wrapper',
-        'WorkItem', 'codecs', 'lockedmethod', 'logging', 'os', 'Queue', 're',
+        'WorkItem', 'codecs', 'lockedmethod', 'logging', 'os', 'pipes', 'Queue',
-        'rmtree', 'safe_makedirs', 'stat', 'subprocess', 'subprocess2', 'sys',
+        're', 'rmtree', 'safe_makedirs', 'stat', 'subprocess', 'subprocess2',
-        'tempfile', 'threading', 'time', 'urlparse',
+        'sys', 'tempfile', 'threading', 'time', 'urlparse',
     ]
     # If this test fails, you should add the relevant test.
     self.compareMembers(gclient_utils, members)