Close sphinx-doc#6446: Add sphinx.ext.durations to inspect durations …

…of build

CHANGES

@@ -25,6 +25,8 @@ Deprecated
 Features added
 --------------
 
+* #6446: duration: Add ``sphinx.ext.durations`` to inspect which documents slow
+  down the build
 * #6707: C++, support bit-fields.
 * #267: html: Eliminate prompt characters of doctest block from copyable text
 * #6548: html: Use favicon for OpenSearch if available

doc/usage/extensions/duration.rst

@@ -0,0 +1,11 @@
+:mod:`sphinx.ext.duration` -- Measure durations of Sphinx processing
+====================================================================
+
+.. module:: sphinx.ext.duration
+   :synopsis: Measure durations of Sphinx processing
+
+.. versionadded:: 2.3
+
+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.

doc/usage/extensions/index.rst

@@ -23,6 +23,7 @@ These extensions are built in and can be activated by respective entries in the
    autosummary
    coverage
    doctest
+   duration
    extlinks
    githubpages
    graphviz

sphinx/ext/duration.py

@@ -0,0 +1,96 @@
+"""
+    sphinx.ext.duration
+    ~~~~~~~~~~~~~~~~~~~
+
+    Measure durations of Sphinx processing.
+
+    :copyright: Copyright 2007-2019 by the Sphinx team, see AUTHORS.
+    :license: BSD, see LICENSE for details.
+"""
+
+from datetime import datetime, timedelta
+from itertools import islice
+from operator import itemgetter
+from typing import cast
+from typing import Dict, List
+
+from docutils import nodes
+
+from sphinx.application import Sphinx
+from sphinx.domains import Domain
+from sphinx.locale import __
+from sphinx.util import logging
+
+logger = logging.getLogger(__name__)
+
+
+class DurationDomain(Domain):
+    """A domain for durations of Sphinx processing."""
+    name = 'duration'
+
+    @property
+    def reading_durations(self) -> Dict[str, timedelta]:
+        return self.data.setdefault('reading_durations', {})
+
+    def note_reading_duration(self, duration: timedelta):
+        self.reading_durations[self.env.docname] = duration
+
+    def clear(self) -> None:
+        self.reading_durations.clear()
+
+    def clear_doc(self, docname: str) -> None:
+        self.reading_durations.pop(docname, None)
+
+    def merge_domaindata(self, docnames: List[str], otherdata: Dict[str, timedelta]) -> None:
+        for docname, duration in otherdata.items():
+            if docname in docnames:
+                self.reading_durations[docname] = duration
+
+
+def on_builder_inited(app: Sphinx) -> None:
+    """Initialize DurationDomain on bootstrap.
+
+    This clears results of last build.
+    """
+    domain = cast(DurationDomain, app.env.get_domain('duration'))
+    domain.clear()
+
+
+def on_source_read(app: Sphinx, docname: str, content: List[str]) -> None:
+    """Start to measure reading duration."""
+    app.env.temp_data['started_at'] = datetime.now()
+
+
+def on_doctree_read(app: Sphinx, doctree: nodes.document) -> None:
+    """Record a reading duration."""
+    started_at = app.env.temp_data.get('started_at')
+    duration = datetime.now() - started_at
+    domain = cast(DurationDomain, app.env.get_domain('duration'))
+    domain.note_reading_duration(duration)
+
+
+def on_build_finished(app: Sphinx, error):
+    """Display duration ranking on current build."""
+    domain = cast(DurationDomain, app.env.get_domain('duration'))
+    durations = sorted(domain.reading_durations.items(), key=itemgetter(1), reverse=True)
+    if not durations:
+        return
+
+    logger.info('')
+    logger.info(__('====================== slowest reading durations ======================='))
+    for docname, d in islice(durations, 5):
+        logger.info('%d.%03d %s', d.seconds, d.microseconds / 1000, docname)
+
+
+def setup(app):
+    app.add_domain(DurationDomain)
+    app.connect('builder-inited', on_builder_inited)
+    app.connect('source-read', on_source_read)
+    app.connect('doctree-read', on_doctree_read)
+    app.connect('build-finished', on_build_finished)
+
+    return {
+        'version': 'builtin',
+        'parallel_read_safe': True,
+        'parallel_write_safe': True,
+    }

tests/test_ext_duration.py

@@ -0,0 +1,21 @@
+"""
+    test_ext_duration
+    ~~~~~~~~~~~~~~~~~
+
+    Test sphinx.ext.duration extension.
+
+    :copyright: Copyright 2007-2019 by the Sphinx team, see AUTHORS.
+    :license: BSD, see LICENSE for details.
+"""
+
+import re
+import pytest
+
+
+@pytest.mark.sphinx('dummy', testroot='basic',
+                    confoverrides={'extensions': ['sphinx.ext.duration']})
+def test_githubpages(app, status, warning):
+    app.build()
+
+    assert 'slowest reading durations' in status.getvalue()
+    assert re.search('\\d+\\.\\d{3} index\n', status.getvalue())