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

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)
 
 

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):