From 61a0ba43cfd4ff66f51a9d73dcd8ed6f6a6d9915 Mon Sep 17 00:00:00 2001 From: "Ahmad A. Hussein" Date: Wed, 22 Jul 2020 17:37:52 +0200 Subject: [PATCH] Refs #31811 -- Added optional timing outputs to the test runner. --- django/core/management/commands/test.py | 8 +-- django/test/runner.py | 26 +++++++--- django/test/utils.py | 59 ++++++++++++++++++----- docs/ref/django-admin.txt | 6 +++ docs/releases/3.2.txt | 8 +++ docs/topics/testing/advanced.txt | 16 ++++-- tests/runtests.py | 30 ++++++++---- tests/test_runner/test_discover_runner.py | 22 ++++++++- tests/test_runner/tests.py | 7 ++- 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): """