From 9a7c914b9ed1aa310d4248fdf61b4ce701b9a0f4 Mon Sep 17 00:00:00 2001
From: Takeshi KOMIYA <i.tkomiya@gmail.com>
Date: Sat, 14 Dec 2019 17:03:27 +0900
Subject: [PATCH] Close #6446: Add sphinx.ext.durations to inspect durations of
 build

---
 CHANGES                           |  2 +
 doc/usage/extensions/duration.rst | 11 ++++
 sphinx/ext/duration.py            | 96 +++++++++++++++++++++++++++++++
 tests/test_ext_duration.py        | 21 +++++++
 4 files changed, 130 insertions(+)
 create mode 100644 doc/usage/extensions/duration.rst
 create mode 100644 sphinx/ext/duration.py
 create mode 100644 tests/test_ext_duration.py

diff --git a/CHANGES b/CHANGES
index 65b8e47c4bb..3a4d4d1386a 100644
--- a/CHANGES
+++ b/CHANGES
@@ -44,6 +44,8 @@ Features added
 * #6816: linkcheck: Add :confval:`linkcheck_auth` option to provide
   authentication information when doing ``linkcheck`` builds
 * #6872: linkcheck: Handles HTTP 308 Permanent Redirect
+* #6446: duration: Add ``sphinx.ext.durations`` to inspect which documents slow
+  down the build
 
 Bugs fixed
 ----------
diff --git a/doc/usage/extensions/duration.rst b/doc/usage/extensions/duration.rst
new file mode 100644
index 00000000000..c5754998402
--- /dev/null
+++ b/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.
diff --git a/sphinx/ext/duration.py b/sphinx/ext/duration.py
new file mode 100644
index 00000000000..1286e49ec18
--- /dev/null
+++ b/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,
+    }
diff --git a/tests/test_ext_duration.py b/tests/test_ext_duration.py
new file mode 100644
index 00000000000..65ea1eef7da
--- /dev/null
+++ b/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())