Print test duration in verbose mode.

This is useful to diagnose slow tests. Make this multiprocessing aware. Stop
printing when the commands are added but use the proper message system instead.

R=iannucci@chromium.org
BUG=

Review URL: https://codereview.chromium.org/99453003

git-svn-id: svn://svn.chromium.org/chrome/trunk/tools/depot_tools@238388 0039d316-1c4b-4281-b951-d872f2087c98

presubmit_canned_checks.py

@@ -550,7 +550,6 @@ def GetUnitTests(input_api, output_api, unit_tests):
       cmd = [input_api.python_executable]
     cmd.append(unit_test)
     if input_api.verbose:
-      print('Running %s' % unit_test)
       cmd.append('--verbose')
     results.append(input_api.Command(
         name=unit_test,

presubmit_support.py

@@ -15,7 +15,6 @@ __version__ = '1.7.0'
 import cpplint
 import cPickle  # Exposed through the API.
 import cStringIO  # Exposed through the API.
-import collections
 import contextlib
 import fnmatch
 import glob
@@ -56,8 +55,14 @@ class PresubmitFailure(Exception):
   pass
 
 
-CommandData = collections.namedtuple('CommandData',
-                                     ['name', 'cmd', 'kwargs', 'message'])
+class CommandData(object):
+  def __init__(self, name, cmd, kwargs, message):
+    self.name = name
+    self.cmd = cmd
+    self.kwargs = kwargs
+    self.message = message
+    self.info = None
+
 
 def normpath(path):
   '''Version of os.path.normpath that also changes backward slashes to
@@ -468,8 +473,7 @@ class InputApi(object):
     """Returns if a change is TBR'ed."""
     return 'TBR' in self.change.tags
 
-  @staticmethod
-  def RunTests(tests_mix, parallel=True):
+  def RunTests(self, tests_mix, parallel=True):
     tests = []
     msgs = []
     for t in tests_mix:
@@ -478,6 +482,8 @@ class InputApi(object):
       else:
         assert issubclass(t.message, _PresubmitResult)
         tests.append(t)
+        if self.verbose:
+          t.info = _PresubmitNotifyResult
     if len(tests) > 1 and parallel:
       pool = multiprocessing.Pool()
       # async recipe works around multiprocessing bug handling Ctrl-C
@@ -1352,17 +1358,28 @@ def canned_check_filter(method_names):
     for name, method in filtered.iteritems():
       setattr(presubmit_canned_checks, name, method)
 
+
 def CallCommand(cmd_data):
-  # multiprocessing needs a top level function with a single argument.
+  """Runs an external program, potentially from a child process created by the
+  multiprocessing module.
+
+  multiprocessing needs a top level function with a single argument.
+  """
   cmd_data.kwargs['stdout'] = subprocess.PIPE
   cmd_data.kwargs['stderr'] = subprocess.STDOUT
   try:
+    start = time.time()
     (out, _), code = subprocess.communicate(cmd_data.cmd, **cmd_data.kwargs)
-    if code != 0:
-      return cmd_data.message('%s failed\n%s' % (cmd_data.name, out))
+    duration = time.time() - start
   except OSError as e:
+    duration = time.time() - start
+    return cmd_data.message(
+        '%s exec failure (%4.2fs)\n   %s' % (cmd_data.name, duration, e))
+  if code != 0:
     return cmd_data.message(
-        '%s exec failure\n   %s' % (cmd_data.name, e))
+        '%s (%4.2fs) failed\n%s' % (cmd_data.name, duration, out))
+  if cmd_data.info:
+    return cmd_data.info('%s (%4.2fs)' % (cmd_data.name, duration))
 
 
 def Main(argv):

tests/presubmit_unittest.py

@@ -7,6 +7,7 @@
 
 # pylint: disable=E1101,E1103
 
+import functools
 import logging
 import os
 import StringIO
@@ -169,7 +170,7 @@ class PresubmitUnittest(PresubmitTestsBase):
       'marshal', 'normpath', 'optparse', 'os', 'owners', 'pickle',
       'presubmit_canned_checks', 'random', 're', 'rietveld', 'scm',
       'subprocess', 'sys', 'tempfile', 'time', 'traceback', 'types', 'unittest',
-      'urllib2', 'warn', 'collections', 'multiprocessing',
+      'urllib2', 'warn', 'multiprocessing',
     ]
     # If this test fails, you should add the relevant test.
     self.compareMembers(presubmit, members)
@@ -1720,7 +1721,8 @@ class CannedChecksUnittest(PresubmitTestsBase):
     input_api.time = time
     input_api.canned_checks = presubmit_canned_checks
     input_api.Command = presubmit.CommandData
-    input_api.RunTests = presubmit.InputApi.RunTests
+    input_api.RunTests = functools.partial(
+        presubmit.InputApi.RunTests, input_api)
     return input_api
 
   def testMembersChanged(self):
@@ -2362,7 +2364,7 @@ class CannedChecksUnittest(PresubmitTestsBase):
     self.assertEquals(len(results), 1)
     self.assertEquals(results[0].__class__,
                       presubmit.OutputApi.PresubmitNotifyResult)
-    self.assertEquals('test_module failed\nfoo', results[0]._message)
+    self.assertEquals('test_module (0.00s) failed\nfoo', results[0]._message)
 
   def testRunPythonUnitTestsFailureCommitting(self):
     input_api = self.MockInputApi(None, True)
@@ -2374,7 +2376,7 @@ class CannedChecksUnittest(PresubmitTestsBase):
         input_api, presubmit.OutputApi, ['test_module'])
     self.assertEquals(len(results), 1)
     self.assertEquals(results[0].__class__, presubmit.OutputApi.PresubmitError)
-    self.assertEquals('test_module failed\nfoo', results[0]._message)
+    self.assertEquals('test_module (0.00s) failed\nfoo', results[0]._message)
 
   def testRunPythonUnitTestsSuccess(self):
     input_api = self.MockInputApi(None, False)
@@ -2660,10 +2662,12 @@ class CannedChecksUnittest(PresubmitTestsBase):
         input_api,
         presubmit.OutputApi,
         unit_tests)
-    self.assertEqual(1, len(results))
+    self.assertEqual(2, len(results))
+    self.assertEqual(
+        presubmit.OutputApi.PresubmitNotifyResult, results[0].__class__)
     self.assertEqual(
-        presubmit.OutputApi.PresubmitPromptWarning, results[0].__class__)
-    self.checkstdout('Running allo\nRunning bar.py\n')
+        presubmit.OutputApi.PresubmitPromptWarning, results[1].__class__)
+    self.checkstdout('')
 
   def testCannedRunUnitTestsInDirectory(self):
     change = presubmit.Change(
@@ -2689,9 +2693,10 @@ class CannedChecksUnittest(PresubmitTestsBase):
         'random_directory',
         whitelist=['^a$', '^b$'],
         blacklist=['a'])
-    self.assertEqual(results, [])
-    self.checkstdout(
-        'Running %s\n' % presubmit.os.path.join('random_directory', 'b'))
+    self.assertEqual(1, len(results))
+    self.assertEqual(
+        presubmit.OutputApi.PresubmitNotifyResult, results[0].__class__)
+    self.checkstdout('')
 
   def testPanProjectChecks(self):
     # Make sure it accepts both list and tuples.