Refs #31811 -- Added optional timing outputs to the test runner.

9 files changed, 144 insertions, 38 deletions

diff --git a/django/core/management/commands/test.py b/django/core/management/commands/test.py
index 679dbc01ea..35e7b73871 100644
--- a/django/core/management/commands/test.py
+++ b/django/core/management/commands/test.py
@@ -3,7 +3,7 @@ import sys
 from django.conf import settings
 from django.core.management.base import BaseCommand
 from django.core.management.utils import get_command_line_option
-from django.test.utils import get_runner
+from django.test.utils import NullTimeKeeper, TimeKeeper, get_runner
 
 
 class Command(BaseCommand):
@@ -49,8 +49,10 @@ class Command(BaseCommand):
     def handle(self, *test_labels, **options):
         TestRunner = get_runner(settings, options['testrunner'])
 
+        time_keeper = TimeKeeper() if options.get('timing', False) else NullTimeKeeper()
         test_runner = TestRunner(**options)
-        failures = test_runner.run_tests(test_labels)
-
+        with time_keeper.timed('Total run'):
+            failures = test_runner.run_tests(test_labels)
+        time_keeper.print_results()
         if failures:
             sys.exit(1)
diff --git a/django/test/runner.py b/django/test/runner.py
index ddf56b336f..83f06c72f3 100644
--- a/django/test/runner.py
+++ b/django/test/runner.py
@@ -16,8 +16,9 @@ from django.core.management import call_command
 from django.db import connections
 from django.test import SimpleTestCase, TestCase
 from django.test.utils import (
-    setup_databases as _setup_databases, setup_test_environment,
-    teardown_databases as _teardown_databases, teardown_test_environment,
+    NullTimeKeeper, TimeKeeper, setup_databases as _setup_databases,
+    setup_test_environment, teardown_databases as _teardown_databases,
+    teardown_test_environment,
 )
 from django.utils.datastructures import OrderedSet
 from django.utils.version import PY37
@@ -437,7 +438,8 @@ class DiscoverRunner:
                  interactive=True, failfast=False, keepdb=False,
                  reverse=False, debug_mode=False, debug_sql=False, parallel=0,
                  tags=None, exclude_tags=None, test_name_patterns=None,
-                 pdb=False, buffer=False, enable_faulthandler=True, **kwargs):
+                 pdb=False, buffer=False, enable_faulthandler=True,
+                 timing=False, **kwargs):
 
         self.pattern = pattern
         self.top_level = top_level
@@ -466,6 +468,7 @@ class DiscoverRunner:
                 '--parallel=1 to use it.'
             )
         self.test_name_patterns = None
+        self.time_keeper = TimeKeeper() if timing else NullTimeKeeper()
         if test_name_patterns:
             # unittest does not export the _convert_select_pattern function
             # that converts command-line arguments to patterns.
@@ -525,6 +528,12 @@ class DiscoverRunner:
             '--no-faulthandler', action='store_false', dest='enable_faulthandler',
             help='Disables the Python faulthandler module during tests.',
         )
+        parser.add_argument(
+            '--timing', action='store_true',
+            help=(
+                'Output timings, including database set up and total run time.'
+            ),
+        )
         if PY37:
             parser.add_argument(
                 '-k', action='append', dest='test_name_patterns',
@@ -624,8 +633,8 @@ class DiscoverRunner:
 
     def setup_databases(self, **kwargs):
         return _setup_databases(
-            self.verbosity, self.interactive, self.keepdb, self.debug_sql,
-            self.parallel, **kwargs
+            self.verbosity, self.interactive, time_keeper=self.time_keeper, keepdb=self.keepdb,
+            debug_sql=self.debug_sql, parallel=self.parallel, **kwargs
         )
 
     def get_resultclass(self):
@@ -704,7 +713,8 @@ class DiscoverRunner:
         self.setup_test_environment()
         suite = self.build_suite(test_labels, extra_tests)
         databases = self.get_databases(suite)
-        old_config = self.setup_databases(aliases=databases)
+        with self.time_keeper.timed('Total database setup'):
+            old_config = self.setup_databases(aliases=databases)
         run_failed = False
         try:
             self.run_checks(databases)
@@ -714,13 +724,15 @@ class DiscoverRunner:
             raise
         finally:
             try:
-                self.teardown_databases(old_config)
+                with self.time_keeper.timed('Total database teardown'):
+                    self.teardown_databases(old_config)
                 self.teardown_test_environment()
             except Exception:
                 # Silence teardown exceptions if an exception was raised during
                 # runs to avoid shadowing it.
                 if not run_failed:
                     raise
+        self.time_keeper.print_results()
         return self.suite_result(suite, result)
 
 
diff --git a/django/test/utils.py b/django/test/utils.py
index d1f7d19546..fec6e7f8a3 100644
--- a/django/test/utils.py
+++ b/django/test/utils.py
@@ -1,5 +1,7 @@
 import asyncio
+import collections
 import logging
+import os
 import re
 import sys
 import time
@@ -152,7 +154,8 @@ def teardown_test_environment():
     del mail.outbox
 
 
-def setup_databases(verbosity, interactive, keepdb=False, debug_sql=False, parallel=0, aliases=None, **kwargs):
+def setup_databases(verbosity, interactive, *, time_keeper, keepdb=False, debug_sql=False, parallel=0,
+                    aliases=None):
     """Create the test databases."""
     test_databases, mirrored_aliases = get_unique_databases_and_mirrors(aliases)
 
@@ -167,19 +170,21 @@ def setup_databases(verbosity, interactive, keepdb=False, debug_sql=False, paral
             # Actually create the database for the first connection
             if first_alias is None:
                 first_alias = alias
-                connection.creation.create_test_db(
-                    verbosity=verbosity,
-                    autoclobber=not interactive,
-                    keepdb=keepdb,
-                    serialize=connection.settings_dict['TEST'].get('SERIALIZE', True),
-                )
+                with time_keeper.timed("  Creating '%s'" % alias):
+                    connection.creation.create_test_db(
+                        verbosity=verbosity,
+                        autoclobber=not interactive,
+                        keepdb=keepdb,
+                        serialize=connection.settings_dict['TEST'].get('SERIALIZE', True),
+                    )
                 if parallel > 1:
                     for index in range(parallel):
-                        connection.creation.clone_test_db(
-                            suffix=str(index + 1),
-                            verbosity=verbosity,
-                            keepdb=keepdb,
-                        )
+                        with time_keeper.timed("  Cloning '%s'" % alias):
+                            connection.creation.clone_test_db(
+                                suffix=str(index + 1),
+                                verbosity=verbosity,
+                                keepdb=keepdb,
+                            )
             # Configure all other connections as mirrors of the first one
             else:
                 connections[alias].creation.set_as_test_mirror(connections[first_alias].settings_dict)
@@ -841,6 +846,36 @@ class isolate_apps(TestContextDecorator):
         setattr(Options, 'default_apps', self.old_apps)
 
 
+class TimeKeeper:
+    def __init__(self):
+        self.records = collections.defaultdict(list)
+
+    @contextmanager
+    def timed(self, name):
+        self.records[name]
+        start_time = time.perf_counter()
+        try:
+            yield
+        finally:
+            end_time = time.perf_counter() - start_time
+            self.records[name].append(end_time)
+
+    def print_results(self):
+        for name, end_times in self.records.items():
+            for record_time in end_times:
+                record = '%s took %.3fs' % (name, record_time)
+                sys.stderr.write(record + os.linesep)
+
+
+class NullTimeKeeper:
+    @contextmanager
+    def timed(self, name):
+        yield
+
+    def print_results(self):
+        pass
+
+
 def tag(*tags):
     """Decorator to add tags to a test class or method."""
     def decorator(obj):
diff --git a/docs/ref/django-admin.txt b/docs/ref/django-admin.txt
index 99cdafd2c8..c1a47dadbd 100644
--- a/docs/ref/django-admin.txt
+++ b/docs/ref/django-admin.txt
@@ -1523,6 +1523,12 @@ Django automatically calls :func:`faulthandler.enable()` when starting the
 tests, which allows it to print a traceback if the interpreter crashes. Pass
 ``--no-faulthandler`` to disable this behavior.
 
+.. django-admin-option:: --timing
+
+.. versionadded:: 3.2
+
+Outputs timings, including including database setup and total run time.
+
 ``testserver``
 --------------
 
diff --git a/docs/releases/3.2.txt b/docs/releases/3.2.txt
index 41929172c6..65a2e6dc99 100644
--- a/docs/releases/3.2.txt
+++ b/docs/releases/3.2.txt
@@ -330,6 +330,11 @@ Tests
   :py:mod:`faulthandler` by default. This can be disabled by using the
   :option:`test --no-faulthandler` option.
 
+* :class:`~django.test.runner.DiscoverRunner` and the
+  :djadmin:`test` management command can now track timings, including database
+  setup and total run time. This can be enabled by using the :option:`test
+  --timing` option.
+
 * :class:`~django.test.Client` now preserves the request query string when
   following 307 and 308 redirects.
 
@@ -454,6 +459,9 @@ Miscellaneous
 
 * Instantiating an abstract model now raises ``TypeError``.
 
+* Keyword arguments to :func:`~django.test.utils.setup_databases` are now
+  keyword-only.
+
 .. _deprecated-features-3.2:
 
 Features deprecated in 3.2
diff --git a/docs/topics/testing/advanced.txt b/docs/topics/testing/advanced.txt
index 06bd351ccf..96fadf96b3 100644
--- a/docs/topics/testing/advanced.txt
+++ b/docs/topics/testing/advanced.txt
@@ -510,7 +510,7 @@ behavior. This class defines the ``run_tests()`` entry point, plus a
 selection of other methods that are used to by ``run_tests()`` to set up,
 execute and tear down the test suite.
 
-.. class:: DiscoverRunner(pattern='test*.py', top_level=None, verbosity=1, interactive=True, failfast=False, keepdb=False, reverse=False, debug_mode=False, debug_sql=False, test_name_patterns=None, pdb=False, buffer=False, enable_faulthandler=True, **kwargs)
+.. class:: DiscoverRunner(pattern='test*.py', top_level=None, verbosity=1, interactive=True, failfast=False, keepdb=False, reverse=False, debug_mode=False, debug_sql=False, test_name_patterns=None, pdb=False, buffer=False, enable_faulthandler=True, timing=True, **kwargs)
 
     ``DiscoverRunner`` will search for tests in any file matching ``pattern``.
 
@@ -560,6 +560,9 @@ execute and tear down the test suite.
     If ``enable_faulthandler`` is ``True``, :py:mod:`faulthandler` will be
     enabled.
 
+    If ``timing`` is ``True``, test timings, including database setup and total
+    run time, will be shown.
+
     Django may, from time to time, extend the capabilities of the test runner
     by adding new arguments. The ``**kwargs`` declaration allows for this
     expansion. If you subclass ``DiscoverRunner`` or write your own test
@@ -576,7 +579,7 @@ execute and tear down the test suite.
 
     .. versionadded:: 3.2
 
-        The ``enable_faulthandler`` argument was added.
+        The ``enable_faulthandler`` and ``timing`` arguments were added.
 
 Attributes
 ~~~~~~~~~~
@@ -659,7 +662,7 @@ Methods
 
     Returns a ``TestSuite`` instance ready to be run.
 
-.. method:: DiscoverRunner.setup_databases(**kwargs)
+.. method:: DiscoverRunner.setup_databases(verbosity, interactive, **kwargs)
 
     Creates the test databases by calling
     :func:`~django.test.utils.setup_databases`.
@@ -723,7 +726,7 @@ utility methods in the ``django.test.utils`` module.
     Performs global post-test teardown, such as removing instrumentation from
     the template system and restoring normal email services.
 
-.. function:: setup_databases(verbosity, interactive, keepdb=False, debug_sql=False, parallel=0, aliases=None, **kwargs)
+.. function:: setup_databases(verbosity, interactive, *, time_keeper, keepdb=False, debug_sql=False, parallel=0, aliases=None, **kwargs)
 
     Creates the test databases.
 
@@ -735,6 +738,11 @@ utility methods in the ``django.test.utils`` module.
     databases should be setup for. If it's not provided, it defaults to all of
     :setting:`DATABASES` aliases.
 
+    .. versionchanged:: 3.2
+
+        The ``time_keeper`` kwarg was added, and all kwargs were made
+        keyword-only.
+
 .. function:: teardown_databases(old_config, parallel=0, keepdb=False)
 
     Destroys the test databases, restoring pre-test conditions.
diff --git a/tests/runtests.py b/tests/runtests.py
index d79b4b393e..db32da13eb 100755
--- a/tests/runtests.py
+++ b/tests/runtests.py
@@ -23,7 +23,7 @@ else:
     from django.test import TestCase, TransactionTestCase
     from django.test.runner import default_test_processes
     from django.test.selenium import SeleniumTestCaseBase
-    from django.test.utils import get_runner
+    from django.test.utils import NullTimeKeeper, TimeKeeper, get_runner
     from django.utils.deprecation import (
         RemovedInDjango40Warning, RemovedInDjango41Warning,
     )
@@ -287,7 +287,8 @@ class ActionSelenium(argparse.Action):
 
 def django_tests(verbosity, interactive, failfast, keepdb, reverse,
                  test_labels, debug_sql, parallel, tags, exclude_tags,
-                 test_name_patterns, start_at, start_after, pdb, buffer):
+                 test_name_patterns, start_at, start_after, pdb, buffer,
+                 timing):
     state = setup(verbosity, test_labels, parallel, start_at, start_after)
     extra_tests = []
 
@@ -309,6 +310,7 @@ def django_tests(verbosity, interactive, failfast, keepdb, reverse,
         test_name_patterns=test_name_patterns,
         pdb=pdb,
         buffer=buffer,
+        timing=timing,
     )
     failures = test_runner.run_tests(
         test_labels or get_installed(),
@@ -508,6 +510,10 @@ if __name__ == "__main__":
         '-b', '--buffer', action='store_true',
         help='Discard output of passing tests.',
     )
+    parser.add_argument(
+        '--timing', action='store_true',
+        help='Output timings, including database set up and total run time.',
+    )
     if PY37:
         parser.add_argument(
             '-k', dest='test_name_patterns', action='append',
@@ -568,13 +574,17 @@ if __name__ == "__main__":
             options.start_at, options.start_after,
         )
     else:
-        failures = django_tests(
-            options.verbosity, options.interactive, options.failfast,
-            options.keepdb, options.reverse, options.modules,
-            options.debug_sql, options.parallel, options.tags,
-            options.exclude_tags,
-            getattr(options, 'test_name_patterns', None),
-            options.start_at, options.start_after, options.pdb, options.buffer,
-        )
+        time_keeper = TimeKeeper() if options.timing else NullTimeKeeper()
+        with time_keeper.timed('Total run'):
+            failures = django_tests(
+                options.verbosity, options.interactive, options.failfast,
+                options.keepdb, options.reverse, options.modules,
+                options.debug_sql, options.parallel, options.tags,
+                options.exclude_tags,
+                getattr(options, 'test_name_patterns', None),
+                options.start_at, options.start_after, options.pdb, options.buffer,
+                options.timing,
+            )
+        time_keeper.print_results()
         if failures:
             sys.exit(1)
diff --git a/tests/test_runner/test_discover_runner.py b/tests/test_runner/test_discover_runner.py
index 8caacd2620..183e283d08 100644
--- a/tests/test_runner/test_discover_runner.py
+++ b/tests/test_runner/test_discover_runner.py
@@ -8,7 +8,9 @@ from unittest import (
 from django.db import connections
 from django.test import SimpleTestCase
 from django.test.runner import DiscoverRunner
-from django.test.utils import captured_stderr, captured_stdout
+from django.test.utils import (
+    NullTimeKeeper, TimeKeeper, captured_stderr, captured_stdout,
+)
 from django.utils.version import PY37
 
 
@@ -324,6 +326,24 @@ class DiscoverRunnerTests(SimpleTestCase):
             DiscoverRunner(enable_faulthandler=False)
             mocked_enable.assert_not_called()
 
+    def test_timings_not_captured(self):
+        runner = DiscoverRunner(timing=False)
+        with captured_stderr() as stderr:
+            with runner.time_keeper.timed('test'):
+                pass
+            runner.time_keeper.print_results()
+        self.assertTrue(isinstance(runner.time_keeper, NullTimeKeeper))
+        self.assertNotIn('test', stderr.getvalue())
+
+    def test_timings_captured(self):
+        runner = DiscoverRunner(timing=True)
+        with captured_stderr() as stderr:
+            with runner.time_keeper.timed('test'):
+                pass
+            runner.time_keeper.print_results()
+        self.assertTrue(isinstance(runner.time_keeper, TimeKeeper))
+        self.assertIn('test', stderr.getvalue())
+
 
 class DiscoverRunnerGetDatabasesTests(SimpleTestCase):
     runner = DiscoverRunner(verbosity=2)
diff --git a/tests/test_runner/tests.py b/tests/test_runner/tests.py
index 85e4e75720..e12ea3b11a 100644
--- a/tests/test_runner/tests.py
+++ b/tests/test_runner/tests.py
@@ -14,7 +14,7 @@ from django.core.management.base import SystemCheckError
 from django.test import TransactionTestCase, skipUnlessDBFeature, testcases
 from django.test.runner import DiscoverRunner
 from django.test.testcases import connections_support_transactions
-from django.test.utils import dependency_ordered
+from django.test.utils import captured_stderr, dependency_ordered
 
 from .models import B, Person, Through
 
@@ -148,6 +148,11 @@ class ManageCommandTests(unittest.TestCase):
         with self.assertRaises(AttributeError):
             call_command('test', 'sites', testrunner='test_runner.NonexistentRunner')
 
+    def test_time_recorded(self):
+        with captured_stderr() as stderr:
+            call_command('test', '--timing', 'sites', testrunner='test_runner.tests.MockTestRunner')
+        self.assertIn('Total run took', stderr.getvalue())
+
 
 class CustomTestRunnerOptionsSettingsTests(AdminScriptTestCase):
     """