Incremental GC causes a significant slowdown for Sphinx

@nascheme

Bug report

A significant performance regression in Sphinx caused by changes in CPython 3.13

Here is a script that does the following things:

Replaces the contents of all CPython documentation files except Doc/library/typing.rst with simply "foo"
Creates a virtual environment
Installs our doc dependencies into the environment (making sure that we use pure-Python versions for all doc dependencies rather than built wheels that might include C extensions)
Times how long it takes to build the docs using that environment
Restores all the modified docs files and deletes the virtual environment again

The script

import contextlib
import shutil
import subprocess
import time
import venv
from pathlib import Path

def run(args):
    try:
        subprocess.run(args, check=True, capture_output=True, text=True)
    except subprocess.CalledProcessError as e:
        print(e.stdout)
        print(e.stderr)
        raise


with contextlib.chdir("Doc"):
    try:
        for path in Path(".").iterdir():
            if path.is_dir() and not str(path).startswith("."):
                for doc_path in path.rglob("*.rst"):
                    if doc_path != Path("library/typing.rst"):
                        doc_path.write_text("foo")

        venv.create(".venv", with_pip=True)

        run([
            ".venv/bin/python",
            "-m",
            "pip",
            "install",
            "-r",
            "requirements.txt",
            "--no-binary=':all:'",
        ])

        start = time.perf_counter()

        run([
            ".venv/bin/python",
            "-m",
            "sphinx",
            "-b",
            "html",
            ".",
            "build/html",
            "library/typing.rst",
        ])

        print(time.perf_counter() - start)
        shutil.rmtree(".venv")
        shutil.rmtree("build")
    finally:
        subprocess.run(["git", "restore", "."], check=True, capture_output=True)

Using a PGO-optimized build with LTO enabled, the script reports that there is a significant performance regression in Sphinx's parsing and building of library/typing.rst between v3.13.0a1 and 909c6f7:

On v13.0a1 the script reports a Sphinx build time of between 1.27s and 1.29s (I ran the script several times)
On ede1504, a Sphinx build time of between 1.76 and 1.82s is reported by the script (a roughly 48% regression).

A similar regression is reported in this (much slower) variation of the script that builds the entire set of CPython's documentation rather than just library/typing.rst.

More comprehensive variation of the script

import contextlib
import shutil
import subprocess
import time
import venv

def run(args):
    subprocess.run(args, check=True, text=True)


with contextlib.chdir("Doc"):
    venv.create(".venv", with_pip=True)

    run([
        ".venv/bin/python",
        "-m",
        "pip",
        "install",
        "-r",
        "requirements.txt",
        "--no-binary=':all:'",
    ])

    start = time.perf_counter()

    run([
        ".venv/bin/python",
        "-m",
        "sphinx",
        "-b",
        "html",
        ".",
        "build/html",
    ])

    print(time.perf_counter() - start)
    shutil.rmtree(".venv")
    shutil.rmtree("build")

The PGO-optimized timings for building the entire CPython documentation is as follows:

v3.13.0a1: 45.5s
ede1504: 62.7s

This indicates a 38% performance regression for building the entire set of CPython's documentation.

Cause of the performance regression

This performance regression was initially discovered in #118891: in our own CI, we use a fresh build of CPython in our Doctest CI workflow (since otherwise, we wouldn't be testing the tip of the main branch), and it was observed that the CI job was taking significantly longer on the 3.13 branch than the 3.12 branch. In the context of our CI, the performance regression is even worse, because of the fact that our Doctest CI workflow uses a debug build rather than a PGO-optimized build, and the regression is even more pronounced in a Debug build.

Using a debug build, I used the first script posted above to bisect the performance regression to commit 1530932 (below), which seemed to cause a performance regression of around 300% in a debug build

15309329b65a285cb7b3071f0f08ac964b61411b is the first bad commit
commit 15309329b65a285cb7b3071f0f08ac964b61411b
Author: Mark Shannon <mark@hotpy.org>
Date:   Wed Mar 20 08:54:42 2024 +0000

    GH-108362: Incremental Cycle GC (GH-116206)

 Doc/whatsnew/3.13.rst                              |  30 +
 Include/internal/pycore_gc.h                       |  41 +-
 Include/internal/pycore_object.h                   |  18 +-
 Include/internal/pycore_runtime_init.h             |   8 +-
 Lib/test/test_gc.py                                |  72 +-
 .../2024-01-07-04-22-51.gh-issue-108362.oB9Gcf.rst |  12 +
 Modules/gcmodule.c                                 |  25 +-
 Objects/object.c                                   |  21 +
 Objects/structseq.c                                |   5 +-
 Python/gc.c                                        | 806 +++++++++++++--------
 Python/gc_free_threading.c                         |  23 +-
 Python/import.c                                    |   2 +-
 Python/optimizer.c                                 |   2 +-
 Tools/gdb/libpython.py                             |   7 +-
 14 files changed, 684 insertions(+), 388 deletions(-)
 create mode 100644 Misc/NEWS.d/next/Core and Builtins/2024-01-07-04-22-51.gh-issue-108362.oB9Gcf.rst

Performance was then significantly improved by commit e28477f (below), but it's unfortunately still the case that Sphinx is far slower on Python 3.13 than on Python 3.12:

commit e28477f214276db941e715eebc8cdfb96c1207d9
Author: Mark Shannon <mark@hotpy.org>
Date:   Fri Mar 22 18:43:25 2024 +0000

    GH-117108: Change the size of the GC increment to about 1% of the total heap size. (GH-117120)

 Include/internal/pycore_gc.h                       |  3 +-
 Lib/test/test_gc.py                                | 35 +++++++++++++++-------
 .../2024-03-21-12-10-11.gh-issue-117108._6jIrB.rst |  3 ++
 Modules/gcmodule.c                                 |  2 +-
 Python/gc.c                                        | 30 +++++++++----------
 Python/gc_free_threading.c                         |  2 +-
 6 files changed, 47 insertions(+), 28 deletions(-)
 create mode 100644 Misc/NEWS.d/next/Core and Builtins/2024-03-21-12-10-11.gh-issue-117108._6jIrB.rst

See #118891 (comment) for more details on the bisection results.

Profiling by @nascheme in #118891 (comment) and #118891 (comment) also confirms that Sphinx spends a significant amount of time in the GC, so it seems very likely that the changes to introduce an incremental GC in Python 3.13 is the cause of this performance regression.

Cc. @markshannon for expertise on the new incremental GC, and cc. @hugovk / @AA-Turner for Sphinx expertise.

CPython versions tested on:

3.12, 3.13, CPython main branch

Operating systems tested on:

macOS

Linked PRs

I think I wanted to investigate it in sphinx-doc/sphinx#12181 but then I didn't have the motivation nor the time... (and we wanted to avoid keeping opened issues for too long). The root cause was the memory usage for docutils that increased a lot so this might be the reason why we are also seeing those slowdowns.

@AA-Turner

I think I wanted to investigate it in sphinx-doc/sphinx#12181 but then I didn't have the motivation nor the time... (and we wanted to avoid keeping opened issues for too long).

Yes, @AA-Turner mentioned as much in #118891 (comment). This seems like the kind of issue that could cause slowdowns for other workloads as well as Sphinx, however. (But I'll defer to our performance and GC experts on if there are obvious ways to mitigate it.)

@ned-deily

Prompted by @ned-deily, I reran my PGO-optimized timings using --with-lto=full --enable-optimizations builds rather than simply --with-lto --enable-optimizations builds. (Since I'm benchmarking using a Mac, this could have been relevant.) The timings on v3.13.0a1 and main using this build configuration were essentially identical to the ones I reported above, however.

@AlexWaygood

@AlexWaygood Let's rerun after #124538 lands.

Could be cool to make the sphinx build a pyperformance benchmark (I think there might be a docutils pyperf benchmark, wonder if that saw a regression)

@willingc

@willingc I think that's unlikely to make a difference; that issue is related to capsules and probably doesn't interact with the regression we're seeing here.

@hauntsaninja there is a docutils benchmark, https://github.com/python/pyperformance/tree/main/pyperformance/data-files/benchmarks/bm_docutils. Looks like it builds a bunch of RST files, though not CPython's own docs. According to Michael that benchmark didn't show a regression, so it would be interesting to figure out what's different about the CPython docs relative to that benchmark.

According to Michael that benchmark didn't show a regression

There is a bit of a regression actually, at least in the memory usage as reported by faster-cpython/ideas#668 (roughly a 20% increase of memory). I don't think that's all there is to actually make Sphinx slower.

Thanks Alex for the excellent write-up. A note for reproduction, in my local tests the slowdown could be reproduced just in the parsing step, so you can use 'dummy' instead of 'html' in the reproduction script to save time (as no HTML files are produced).

library/typing.rst

Interestingly I found that when building just that document, timings were broadly the same. However when building everything, 3.13.0a5 was consistently 1.6x faster than 3.13.0a6 (using the built optimised releases from https://www.python.org/downloads/ for Windows, 64 bit).

Could be cool to make the sphinx build a pyperformance benchmark

When I added the Docutils benchmark, Michael Droettboom requested that I/O variables (reading & writing files) be removed as it adds too much noise. There isn't a good way to avoid I/O in Sphinx, unlike with Docutils, unfortunatley. I would be keen to add Sphinx to the benchmark suite.

Looks like it builds a bunch of RST files

Docutils' documentation, we can't use Python's as the Python documentation uses Sphinx-only extensions.

A

Do we also need to check how the Sphinx benchmark looks with a PGO-optimized release build relative to 3.13? (The CI doctest job uses a debug build.)

I agree, for completeness we should confirm that the slowdown has gone from release builds (it was always much more pronounced in debug builds).

A

Do we also need to check how the Sphinx benchmark looks with a PGO-optimized release build relative to 3.13?

On PGO builds on our benchmarking hardware, the Sphinx benchmark is now not significantly different than 3.13.0 and about 2% faster than main prior to #126502 being merged.

@markshannon

Performance is also now unchanged for me locally relative to Python 3.13 (or maybe slightly better!) using the script I posted in #118891 (comment):

main (built using --enable-optimisations --with-lto=full): 37.22s
3.13: 38.15s

Closing as completed. Thanks everybody who helped investigate, and thanks @markshannon for fixing! 🥳

Reopening since #126502 was reverted in #126983 due to buildbot failures

GH-124567: Replace quadratic assert with linear one (GH-127009)

And closing again 🙂

pythonGH-124567: Reduce overhead of debug build for GC. Should help C…

pythonGH-124567: Replace quadratic assert with linear one (pythonGH-1…

Navigation Menu

Repository navigation

Incremental GC causes a significant slowdown for Sphinx #124567

Bug report

A significant performance regression in Sphinx caused by changes in CPython 3.13

Cause of the performance regression

CPython versions tested on:

Operating systems tested on:

Linked PRs

21 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Incremental GC causes a significant slowdown for Sphinx #124567

Description

Bug report

A significant performance regression in Sphinx caused by changes in CPython 3.13

Cause of the performance regression

CPython versions tested on:

Operating systems tested on:

Linked PRs

Activity

picnixz commented on Sep 26, 2024

AlexWaygood commented on Sep 26, 2024

AlexWaygood commented on Sep 26, 2024

willingc commented on Sep 26, 2024

hauntsaninja commented on Sep 26, 2024

JelleZijlstra commented on Sep 26, 2024

picnixz commented on Sep 26, 2024

AA-Turner commented on Sep 26, 2024

21 remaining items

AA-Turner commented on Nov 18, 2024

mdboom commented on Nov 18, 2024

AlexWaygood commented on Nov 18, 2024

AlexWaygood commented on Nov 19, 2024

markshannon commented on Nov 19, 2024

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions