Add duration to verbose run

pre_commit/commands/run.py

@@ -4,6 +4,7 @@ import logging
 import os
 import re
 import subprocess
+import time
 
 from identify.identify import tags_from_path
 
@@ -99,6 +100,7 @@ def _run_single_hook(classifier, hook, skips, cols, verbose, use_color):
                 cols=cols,
             ),
         )
+        duration = None
         retcode = 0
         files_modified = False
         out = b''
@@ -113,6 +115,7 @@ def _run_single_hook(classifier, hook, skips, cols, verbose, use_color):
                 cols=cols,
             ),
         )
+        duration = None
         retcode = 0
         files_modified = False
         out = b''
@@ -123,7 +126,9 @@ def _run_single_hook(classifier, hook, skips, cols, verbose, use_color):
         diff_cmd = ('git', 'diff', '--no-ext-diff')
         diff_before = cmd_output_b(*diff_cmd, retcode=None)
         filenames = tuple(filenames) if hook.pass_filenames else ()
+        time_before = time.time()
         retcode, out = hook.run(filenames, use_color)
+        duration = round(time.time() - time_before, 2) or 0
         diff_after = cmd_output_b(*diff_cmd, retcode=None)
 
         # if the hook makes changes, fail the commit
@@ -141,6 +146,9 @@ def _run_single_hook(classifier, hook, skips, cols, verbose, use_color):
     if verbose or hook.verbose or retcode or files_modified:
         _subtle_line('- hook id: {}'.format(hook.id), use_color)
 
+        if (verbose or hook.verbose) and duration is not None:
+            _subtle_line('- duration: {}s'.format(duration), use_color)
+
         if retcode:
             _subtle_line('- exit code: {}'.format(retcode), use_color)
 

testing/resources/arbitrary_bytes_repo/.pre-commit-hooks.yaml

@@ -1,6 +1,5 @@
--   id: python3-hook
+-   id: hook
-    name: Python 3 Hook
+    name: hook
-    entry: python3-hook
+    entry: ./hook.sh
-    language: python
+    language: script
-    language_version: python3
     files: \.py$

testing/resources/arbitrary_bytes_repo/hook.sh

@@ -0,0 +1,7 @@
+#!/usr/bin/env bash
+# Intentionally write mixed encoding to the output.  This should not crash
+# pre-commit and should write bytes to the output.
+# '☃'.encode('UTF-8') + '²'.encode('latin1')
+echo -e '\xe2\x98\x83\xb2'
+# exit 1 to trigger printing
+exit 1

testing/resources/arbitrary_bytes_repo/python3_hook.py

@@ -1,13 +0,0 @@
-# -*- coding: utf-8 -*-
-from __future__ import print_function
-from __future__ import unicode_literals
-
-import sys
-
-
-def main():
-    # Intentionally write mixed encoding to the output.  This should not crash
-    # pre-commit and should write bytes to the output.
-    sys.stdout.buffer.write('☃'.encode('UTF-8') + '²'.encode('latin1') + b'\n')
-    # Return 1 to trigger printing
-    return 1

testing/resources/arbitrary_bytes_repo/setup.py

@@ -1,8 +0,0 @@
-from setuptools import setup
-
-setup(
-    name='python3_hook',
-    version='0.0.0',
-    py_modules=['python3_hook'],
-    entry_points={'console_scripts': ['python3-hook=python3_hook:main']},
-)

tests/commands/run_test.py

@@ -5,6 +5,7 @@ import io
 import os.path
 import pipes
 import sys
+import time
 
 import mock
 import pytest
@@ -25,6 +26,7 @@ from testing.fixtures import make_consuming_repo
 from testing.fixtures import modify_config
 from testing.fixtures import read_config
 from testing.fixtures import sample_meta_config
+from testing.fixtures import write_config
 from testing.util import cmd_output_mocked_pre_commit_home
 from testing.util import cwd
 from testing.util import git_commit
@@ -163,36 +165,55 @@ def test_exclude_types_hook_repository(cap_out, store, tempdir_factory):
         assert b'exe' not in printed
 
 
-def test_global_exclude(cap_out, store, tempdir_factory):
+def test_global_exclude(cap_out, store, in_git_dir):
-    git_path = make_consuming_repo(tempdir_factory, 'script_hooks_repo')
+    config = {
-    with cwd(git_path):
+        'exclude': r'^foo\.py$',
-        with modify_config() as config:
+        'repos': [{'repo': 'meta', 'hooks': [{'id': 'identity'}]}],
-            config['exclude'] = '^foo.py$'
+    }
+    write_config('.', config)
     open('foo.py', 'a').close()
     open('bar.py', 'a').close()
     cmd_output('git', 'add', '.')
     opts = run_opts(verbose=True)
-        ret, printed = _do_run(cap_out, store, git_path, opts)
+    ret, printed = _do_run(cap_out, store, str(in_git_dir), opts)
     assert ret == 0
     # Does not contain foo.py since it was excluded
-        expected = b'- hook id: bash_hook\n\nbar.py\nHello World\n\n'
+    assert printed.startswith(b'identity' + b'.' * 65 + b'Passed\n')
-        assert printed.endswith(expected)
+    assert printed.endswith(b'\n\n.pre-commit-config.yaml\nbar.py\n\n')
 
 
-def test_global_files(cap_out, store, tempdir_factory):
+def test_global_files(cap_out, store, in_git_dir):
-    git_path = make_consuming_repo(tempdir_factory, 'script_hooks_repo')
+    config = {
-    with cwd(git_path):
+        'files': r'^bar\.py$',
-        with modify_config() as config:
+        'repos': [{'repo': 'meta', 'hooks': [{'id': 'identity'}]}],
-            config['files'] = '^bar.py$'
+    }
+    write_config('.', config)
     open('foo.py', 'a').close()
     open('bar.py', 'a').close()
     cmd_output('git', 'add', '.')
     opts = run_opts(verbose=True)
-        ret, printed = _do_run(cap_out, store, git_path, opts)
+    ret, printed = _do_run(cap_out, store, str(in_git_dir), opts)
     assert ret == 0
-        # Does not contain foo.py since it was not included
+    # Does not contain foo.py since it was excluded
-        expected = b'- hook id: bash_hook\n\nbar.py\nHello World\n\n'
+    assert printed.startswith(b'identity' + b'.' * 65 + b'Passed\n')
-        assert printed.endswith(expected)
+    assert printed.endswith(b'\n\nbar.py\n\n')
+
+
+@pytest.mark.parametrize(
+    ('t1', 't2', 'expected'),
+    (
+        (1.234, 2., b'\n- duration: 0.77s\n'),
+        (1., 1., b'\n- duration: 0s\n'),
+    ),
+)
+def test_verbose_duration(cap_out, store, in_git_dir, t1, t2, expected):
+    write_config('.', {'repo': 'meta', 'hooks': [{'id': 'identity'}]})
+    cmd_output('git', 'add', '.')
+    opts = run_opts(verbose=True)
+    with mock.patch.object(time, 'time', side_effect=(t1, t2)):
+        ret, printed = _do_run(cap_out, store, str(in_git_dir), opts)
+    assert ret == 0
+    assert expected in printed
 
 
 @pytest.mark.parametrize(

tests/commands/try_repo_test.py

@@ -3,6 +3,9 @@ from __future__ import unicode_literals
 
 import os.path
 import re
+import time
+
+import mock
 
 from pre_commit import git
 from pre_commit.commands.try_repo import try_repo
@@ -40,6 +43,7 @@ def _run_try_repo(tempdir_factory, **kwargs):
 
 
 def test_try_repo_repo_only(cap_out, tempdir_factory):
+    with mock.patch.object(time, 'time', return_value=0.0):
         _run_try_repo(tempdir_factory, verbose=True)
     start, config, rest = _get_out(cap_out)
     assert start == ''
@@ -58,6 +62,7 @@ Bash hook............................................(no files to check)Skipped
 - hook id: bash_hook
 Bash hook................................................................Passed
 - hook id: bash_hook2
+- duration: 0s
 
 test-file