diff --git a/AUTHORS.rst b/AUTHORS.rst index 5ff09219c02..d9cb18b4d0b 100644 --- a/AUTHORS.rst +++ b/AUTHORS.rst @@ -53,6 +53,7 @@ Contributors * Eric Larson -- better error messages * Eric N. Vander Weele -- autodoc improvements * Eric Wieser -- autodoc improvements +* Erik Bedard -- config options for :mod:`sphinx.ext.duration` * Etienne Desautels -- apidoc module * Ezio Melotti -- collapsible sidebar JavaScript * Filip Vavera -- napoleon todo directive diff --git a/CHANGES.rst b/CHANGES.rst index fede8b5177b..1b2bc7b2462 100644 --- a/CHANGES.rst +++ b/CHANGES.rst @@ -19,6 +19,7 @@ Features added * #13439: linkcheck: Permit warning on every redirect with ``linkcheck_allowed_redirects = {}``. Patch by Adam Turner. +* #13468: Add config options to :mod:`sphinx.ext.duration`. Bugs fixed ---------- diff --git a/doc/usage/configuration.rst b/doc/usage/configuration.rst index d14b5d4ec6b..9149c5b2c7b 100644 --- a/doc/usage/configuration.rst +++ b/doc/usage/configuration.rst @@ -1416,6 +1416,7 @@ Options for warning control * ``autosectionlabel.`` * ``autosummary`` * ``autosummary.import_cycle`` + * ``duration`` * ``intersphinx.external`` You can choose from these types. You can also give only the first @@ -1481,6 +1482,9 @@ Options for warning control ``ref.any``, ``toc.duplicate_entry``, ``toc.empty_glob``, and ``toc.not_included``. + .. versionadded:: 8.3 + ``duration``. + Builder options =============== diff --git a/doc/usage/extensions/duration.rst b/doc/usage/extensions/duration.rst index 1213811daf0..96c3238fc76 100644 --- a/doc/usage/extensions/duration.rst +++ b/doc/usage/extensions/duration.rst @@ -6,6 +6,92 @@ .. versionadded:: 2.4 -This extension measures durations of Sphinx processing and show its -result at end of the build. It is useful for inspecting what document -is slowly built. +This extension measures durations of Sphinx processing when reading +documents and is useful for inspecting what document is slowly built. +Durations are printed to console at the end of the build and saved +to a JSON file in :attr:`~sphinx.application.Sphinx.outdir` by default. + +Enable this extension by adding it to your :confval:`extensions` +configuration. + +.. code-block:: python + + extensions = [ + ... + 'sphinx.ext.duration', + ] + +Configuration +============= + +.. confval:: duration_print_slowest + :type: :code-py:`bool` + :default: :code-py:`True` + + Show the slowest durations in the build summary. The durations + are sorted in order from slow to fast. This prints up to + :confval:`duration_n_slowest` durations to the console, e.g.: + + .. code-block:: shell + + ====================== slowest 5 reading durations ======================= + 0.012s toctree + 0.011s admonitions + 0.011s refs + 0.006s docfields + 0.005s figure + + .. versionadded:: 8.3 + +.. confval:: duration_n_slowest + :type: :code-py:`int` + :default: :code-py:`5` + + Maximum number of slowest durations to show in the build summary + when :confval:`duration_print_slowest` is enabled. Only the ``5`` + slowest durations are shown by default. Set this to ``0`` to show + all durations. + + .. versionadded:: 8.3 + +.. confval:: duration_print_total + :type: :code-py:`bool` + :default: :code-py:`True` + + Show the total reading duration in the build summary, e.g.: + + .. code-block:: shell + + ====================== total reading duration ========================== + Total time reading 31 files: + + minutes: 0 + seconds: 3 + milliseconds: 142 + + .. versionadded:: 8.3 + +.. confval:: duration_write_json + :type: :code-py:`str | bool` + :default: :code-py:`'sphinx_reading_durations.json'` + + Write all reading durations to a JSON file in + :attr:`~sphinx.application.Sphinx.outdir`. The file contents are + dict-like and contain the document file paths (relative to + :attr:`~sphinx.application.Sphinx.outdir`) as keys and reading + durations in seconds as values. Set this value to an empty + string or ``False`` to disable writing the file, or set it to a + relative path to customize it. + + This may be useful for testing and setting a limit on reading times. + + .. versionadded:: 8.3 + +.. confval:: duration_limit + :type: :code-py:`float | None` + :default: :code-py:`None` + + Set a duration limit (in seconds) for reading a document. If any + duration exceeds this value, a warning is emitted. + + .. versionadded:: 8.3 diff --git a/sphinx/ext/duration.py b/sphinx/ext/duration.py index 1cf3f7b58d4..b50ea14dd54 100644 --- a/sphinx/ext/duration.py +++ b/sphinx/ext/duration.py @@ -2,10 +2,13 @@ from __future__ import annotations +import json import time +from datetime import datetime, timedelta, timezone from itertools import islice from operator import itemgetter -from typing import TYPE_CHECKING +from pathlib import Path +from typing import TYPE_CHECKING, cast import sphinx from sphinx.domains import Domain @@ -24,6 +27,14 @@ class _DurationDomainData(TypedDict): reading_durations: dict[str, float] +DEFAULT_OPTIONS = { + 'duration_print_total': True, + 'duration_print_slowest': True, + 'duration_n_slowest': 5, + 'duration_write_json': 'sphinx_reading_durations.json', + 'duration_limit': None, +} + logger = logging.getLogger(__name__) @@ -39,6 +50,15 @@ def reading_durations(self) -> dict[str, float]: def note_reading_duration(self, duration: float) -> None: self.reading_durations[self.env.docname] = duration + def warn_reading_duration(self, duration: float, duration_limit: float) -> None: + logger.warning( + __('Reading duration %s exceeded the duration limit %s'), + _format_seconds(duration), + _format_seconds(duration_limit), + type='duration', + location=self.env.docname, + ) + def clear(self) -> None: self.reading_durations.clear() @@ -75,22 +95,79 @@ def on_doctree_read(app: Sphinx, doctree: nodes.document) -> None: domain = app.env.domains['duration'] domain.note_reading_duration(duration) + duration_limit = cast( + 'float | None', + getattr(app.config, 'duration_limit', DEFAULT_OPTIONS['duration_limit']), + ) + if duration_limit is not None and duration > duration_limit: + domain.warn_reading_duration(duration, duration_limit) + def on_build_finished(app: Sphinx, error: Exception) -> None: """Display duration ranking on the current build.""" domain = app.env.domains['duration'] - if not domain.reading_durations: + reading_durations = domain.reading_durations + if not reading_durations: return - durations = sorted( - domain.reading_durations.items(), key=itemgetter(1), reverse=True - ) - logger.info('') - logger.info( - __('====================== slowest reading durations =======================') - ) - for docname, d in islice(durations, 5): - logger.info(f'{d:.3f} {docname}') # NoQA: G004 + # Get default options and update with user-specified values + options = DEFAULT_OPTIONS.copy() + for key in options: + options[key] = getattr(app.config, key, DEFAULT_OPTIONS[key]) + + if options['duration_print_total']: + logger.info('') + logger.info( + __( + '====================== total reading duration ==========================' + ) + ) + + n_files = len(reading_durations) + s = '' if n_files == 1 else 's' + + total = sum(reading_durations.values()) + logger.info('Total time reading %d file%s:\n', n_files, s) + logger.info(_format_seconds(total, multiline=True)) + + if options['duration_print_slowest']: + sorted_durations = sorted( + reading_durations.items(), key=itemgetter(1), reverse=True + ) + n_slowest = cast('int', options['duration_n_slowest']) + + if n_slowest == 0: + n_slowest = len(sorted_durations) + fmt = ' ' + else: + n_slowest = min(n_slowest, len(sorted_durations)) + fmt = f' {n_slowest} ' + + logger.info('') + logger.info( + __( + f'====================== slowest{fmt}reading durations =======================' + ) + ) + + for docname, d in islice(sorted_durations, n_slowest): + logger.info('%s %s', _format_seconds(d), docname) + + logger.info(__('')) + + if write_json := options['duration_write_json']: + # Write to JSON + relpath = ( + Path(write_json) + if isinstance(write_json, (Path, str)) + else Path(cast('Path | str', DEFAULT_OPTIONS['duration_write_json'])) + ) + out_file = Path(app.builder.outdir) / relpath + # Make sure all parent dirs exist + for parent in out_file.parents[: len(relpath.parents) - 1]: + parent.mkdir(exist_ok=True) + with out_file.open('w', encoding='utf-8') as fid: + json.dump(reading_durations, fid, indent=4) def setup(app: Sphinx) -> dict[str, bool | str]: @@ -105,3 +182,18 @@ def setup(app: Sphinx) -> dict[str, bool | str]: 'parallel_read_safe': True, 'parallel_write_safe': True, } + + +def _format_seconds(seconds: float, multiline: bool = False) -> str: + """Convert seconds to a formatted string.""" + if not multiline: + return f'{seconds:.3f}s' + dt = datetime(1, 1, 1, tzinfo=timezone.utc) + timedelta(seconds=seconds) # noqa: UP017 + minutes = dt.hour * 60 + dt.minute + seconds = dt.second + milliseconds = round(dt.microsecond / 1000.0) + return ( + f'minutes: {minutes:>3}\n' + f'seconds: {seconds:>3}\n' + f'milliseconds: {milliseconds:>3}' + ) diff --git a/tests/test_extensions/test_ext_duration.py b/tests/test_extensions/test_ext_duration.py index 2e48e8fe5e5..98edc2adb7c 100644 --- a/tests/test_extensions/test_ext_duration.py +++ b/tests/test_extensions/test_ext_duration.py @@ -2,7 +2,10 @@ from __future__ import annotations +import json +import os import re +from pathlib import Path from typing import TYPE_CHECKING import pytest @@ -15,9 +18,149 @@ 'dummy', testroot='basic', confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, ) -def test_githubpages(app: SphinxTestApp) -> None: +def test_duration(app: SphinxTestApp) -> None: + app.build() + + assert 'slowest 1 reading durations' in app.status.getvalue() + assert re.search('\\d+\\.\\d{3}s index\n', app.status.getvalue()) + + assert 'total reading duration' in app.status.getvalue() + assert 'Total time reading 1 file:' in app.status.getvalue() + assert re.search( + r'minutes:\s*\d+\s*seconds:\s*\d+\s*milliseconds:\s*\d+', app.status.getvalue() + ) + + fname = 'sphinx_reading_durations.json' + assert fname in os.listdir(app.outdir) # noqa: PTH208 + with (Path(app.outdir) / fname).open() as f: + data = json.load(f) + + keys = list(data.keys()) + values = list(data.values()) + assert keys == ['index'] + assert len(values) == 1 + assert isinstance(values[0], float) + + +@pytest.mark.sphinx( + 'dummy', + testroot='root', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_n_slowest_value(app: SphinxTestApp) -> None: + option = 'duration_n_slowest' + n_slowest = 2 + app.add_config_value(option, n_slowest, 'env') + app.build() + + assert f'slowest {n_slowest} reading durations' in app.status.getvalue() + matches = re.findall(r'\d+\.\d{3}s\s+[A-Za-z0-9]+\n', app.status.getvalue()) + assert len(matches) == n_slowest + + +@pytest.mark.sphinx( + 'dummy', + testroot='basic', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_n_slowest_all(app: SphinxTestApp) -> None: + option = 'duration_n_slowest' + n_slowest = 0 + app.add_config_value(option, n_slowest, 'env') app.build() assert 'slowest reading durations' in app.status.getvalue() - assert re.search('\\d+\\.\\d{3} index\n', app.status.getvalue()) + matches = re.findall(r'\d+\.\d{3}s\s+[A-Za-z0-9]+\n', app.status.getvalue()) + assert len(matches) > n_slowest + + +@pytest.mark.sphinx( + 'dummy', + testroot='basic', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_print_slowest_false(app: SphinxTestApp) -> None: + option = 'duration_print_slowest' + print_slowest = False + app.add_config_value(option, print_slowest, 'env') + app.build() + + assert 'slowest reading durations' not in app.status.getvalue() + + +@pytest.mark.sphinx( + 'dummy', + testroot='basic', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_print_total_false(app: SphinxTestApp) -> None: + option = 'duration_print_total' + print_total = False + app.add_config_value(option, print_total, 'env') + app.build() + + assert 'total reading duration' not in app.status.getvalue() + + +@pytest.mark.parametrize('write_json', [True, False]) +@pytest.mark.sphinx( + 'dummy', + testroot='basic', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_write_json_false(app: SphinxTestApp, write_json: bool) -> None: + option = 'duration_write_json' + app.add_config_value(option, write_json, 'env') + app.build() + + expected = Path(app.outdir) / 'sphinx_reading_durations.json' + assert expected.is_file() == write_json + expected.unlink(missing_ok=not write_json) + + +@pytest.mark.sphinx( + 'dummy', + testroot='basic', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_write_json_path(app: SphinxTestApp) -> None: + option = 'duration_write_json' + parent_name = 'durations' + file_name = 'durations.json' + write_json = str(Path(parent_name) / file_name) + app.add_config_value(option, write_json, 'env') + app.build() + + expected_path = Path(app.outdir) / write_json + assert expected_path.parent.is_dir() + assert expected_path.is_file() + assert expected_path.parent.name == parent_name + assert expected_path.name == file_name + + +@pytest.mark.parametrize( + ('duration_limit', 'expect_warning'), [(0.0, True), (1.0, False)] +) +@pytest.mark.sphinx( + 'dummy', + testroot='basic', + confoverrides={'extensions': ['sphinx.ext.duration']}, + freshenv=True, +) +def test_duration_limit( + app: SphinxTestApp, duration_limit: float, expect_warning: bool +) -> None: + app.add_config_value('duration_limit', duration_limit, 'env') + app.build() + + match = r'index\.rst: WARNING: Reading duration \d+\.\d{3}s exceeded the duration limit 0\.000s \[duration\]' + has_warning = re.search(match, app.warning.getvalue()) is not None + assert has_warning == expect_warning