René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Incremental GC causes a significant slowdown for Sphinx","articleBody":"# Bug report\r\n\r\n## A significant performance regression in Sphinx caused by changes in CPython 3.13\r\n\r\nHere is a script that does the following things:\r\n1. Replaces the contents of all CPython documentation files except `Doc/library/typing.rst` with simply `\"foo\"`\r\n2. Creates a virtual environment\r\n3. 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)\r\n4. Times how long it takes to build the docs using that environment\r\n5. Restores all the modified docs files and deletes the virtual environment again\r\n\r\n\u003cdetails\u003e\r\n\u003csummary\u003eThe script\u003c/summary\u003e\r\n\r\n```py\r\nimport contextlib\r\nimport shutil\r\nimport subprocess\r\nimport time\r\nimport venv\r\nfrom pathlib import Path\r\n\r\ndef run(args):\r\n    try:\r\n        subprocess.run(args, check=True, capture_output=True, text=True)\r\n    except subprocess.CalledProcessError as e:\r\n        print(e.stdout)\r\n        print(e.stderr)\r\n        raise\r\n\r\n\r\nwith contextlib.chdir(\"Doc\"):\r\n    try:\r\n        for path in Path(\".\").iterdir():\r\n            if path.is_dir() and not str(path).startswith(\".\"):\r\n                for doc_path in path.rglob(\"*.rst\"):\r\n                    if doc_path != Path(\"library/typing.rst\"):\r\n                        doc_path.write_text(\"foo\")\r\n\r\n        venv.create(\".venv\", with_pip=True)\r\n\r\n        run([\r\n            \".venv/bin/python\",\r\n            \"-m\",\r\n            \"pip\",\r\n            \"install\",\r\n            \"-r\",\r\n            \"requirements.txt\",\r\n            \"--no-binary=':all:'\",\r\n        ])\r\n\r\n        start = time.perf_counter()\r\n\r\n        run([\r\n            \".venv/bin/python\",\r\n            \"-m\",\r\n            \"sphinx\",\r\n            \"-b\",\r\n            \"html\",\r\n            \".\",\r\n            \"build/html\",\r\n            \"library/typing.rst\",\r\n        ])\r\n\r\n        print(time.perf_counter() - start)\r\n        shutil.rmtree(\".venv\")\r\n        shutil.rmtree(\"build\")\r\n    finally:\r\n        subprocess.run([\"git\", \"restore\", \".\"], check=True, capture_output=True)\r\n```\r\n\r\n\u003c/details\u003e\r\n\r\nUsing 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 https://github.com/python/cpython/commit/909c6f718913e713c990d69e6d8a74c05f81e2c2:\r\n- On `v13.0a1` the script reports a Sphinx build time of between 1.27s and 1.29s (I ran the script several times)\r\n- On https://github.com/python/cpython/commit/ede1504c4b37b98636bf935679746ba2932f5677, a Sphinx build time of between 1.76 and 1.82s is reported by the script (a roughly 48% regression).\r\n\r\nA 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`.\r\n\r\n\u003cdetails\u003e\r\n\u003csummary\u003eMore comprehensive variation of the script\u003c/summary\u003e\r\n\r\n```py\r\nimport contextlib\r\nimport shutil\r\nimport subprocess\r\nimport time\r\nimport venv\r\n\r\ndef run(args):\r\n    subprocess.run(args, check=True, text=True)\r\n\r\n\r\nwith contextlib.chdir(\"Doc\"):\r\n    venv.create(\".venv\", with_pip=True)\r\n\r\n    run([\r\n        \".venv/bin/python\",\r\n        \"-m\",\r\n        \"pip\",\r\n        \"install\",\r\n        \"-r\",\r\n        \"requirements.txt\",\r\n        \"--no-binary=':all:'\",\r\n    ])\r\n\r\n    start = time.perf_counter()\r\n\r\n    run([\r\n        \".venv/bin/python\",\r\n        \"-m\",\r\n        \"sphinx\",\r\n        \"-b\",\r\n        \"html\",\r\n        \".\",\r\n        \"build/html\",\r\n    ])\r\n\r\n    print(time.perf_counter() - start)\r\n    shutil.rmtree(\".venv\")\r\n    shutil.rmtree(\"build\")\r\n```\r\n\r\n\u003c/details\u003e\r\n\r\nThe PGO-optimized timings for building the entire CPython documentation is as follows:\r\n- `v3.13.0a1`: 45.5s\r\n- https://github.com/python/cpython/commit/ede1504c4b37b98636bf935679746ba2932f5677: 62.7s\r\n\r\nThis indicates a 38% performance regression for building the entire set of CPython's documentation.\r\n\r\n## Cause of the performance regression\r\n\r\nThis 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.\r\n\r\nUsing a debug build, I used the first script posted above to bisect the performance regression to commit 15309329b65a285cb7b3071f0f08ac964b61411b (below), which seemed to cause a performance regression of around 300% in a debug build\r\n\r\n```\r\n15309329b65a285cb7b3071f0f08ac964b61411b is the first bad commit\r\ncommit 15309329b65a285cb7b3071f0f08ac964b61411b\r\nAuthor: Mark Shannon \u003cmark@hotpy.org\u003e\r\nDate:   Wed Mar 20 08:54:42 2024 +0000\r\n\r\n    GH-108362: Incremental Cycle GC (GH-116206)\r\n\r\n Doc/whatsnew/3.13.rst                              |  30 +\r\n Include/internal/pycore_gc.h                       |  41 +-\r\n Include/internal/pycore_object.h                   |  18 +-\r\n Include/internal/pycore_runtime_init.h             |   8 +-\r\n Lib/test/test_gc.py                                |  72 +-\r\n .../2024-01-07-04-22-51.gh-issue-108362.oB9Gcf.rst |  12 +\r\n Modules/gcmodule.c                                 |  25 +-\r\n Objects/object.c                                   |  21 +\r\n Objects/structseq.c                                |   5 +-\r\n Python/gc.c                                        | 806 +++++++++++++--------\r\n Python/gc_free_threading.c                         |  23 +-\r\n Python/import.c                                    |   2 +-\r\n Python/optimizer.c                                 |   2 +-\r\n Tools/gdb/libpython.py                             |   7 +-\r\n 14 files changed, 684 insertions(+), 388 deletions(-)\r\n create mode 100644 Misc/NEWS.d/next/Core and Builtins/2024-01-07-04-22-51.gh-issue-108362.oB9Gcf.rst\r\n```\r\n\r\nPerformance was then significantly improved by commit e28477f214276db941e715eebc8cdfb96c1207d9 (below), but it's unfortunately still the case that Sphinx is far slower on Python 3.13 than on Python 3.12:\r\n\r\n```\r\ncommit e28477f214276db941e715eebc8cdfb96c1207d9\r\nAuthor: Mark Shannon \u003cmark@hotpy.org\u003e\r\nDate:   Fri Mar 22 18:43:25 2024 +0000\r\n\r\n    GH-117108: Change the size of the GC increment to about 1% of the total heap size. (GH-117120)\r\n\r\n Include/internal/pycore_gc.h                       |  3 +-\r\n Lib/test/test_gc.py                                | 35 +++++++++++++++-------\r\n .../2024-03-21-12-10-11.gh-issue-117108._6jIrB.rst |  3 ++\r\n Modules/gcmodule.c                                 |  2 +-\r\n Python/gc.c                                        | 30 +++++++++----------\r\n Python/gc_free_threading.c                         |  2 +-\r\n 6 files changed, 47 insertions(+), 28 deletions(-)\r\n create mode 100644 Misc/NEWS.d/next/Core and Builtins/2024-03-21-12-10-11.gh-issue-117108._6jIrB.rst\r\n```\r\n\r\nSee https://github.com/python/cpython/issues/118891#issuecomment-2375334948 for more details on the bisection results.\r\n\r\nProfiling by @nascheme in https://github.com/python/cpython/issues/118891#issuecomment-2375362608 and https://github.com/python/cpython/issues/118891#issuecomment-2375446761 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.\r\n\r\nCc. @markshannon for expertise on the new incremental GC, and cc. @hugovk / @AA-Turner for Sphinx expertise.\r\n\r\n### CPython versions tested on:\r\n\r\n3.12, 3.13, CPython main branch\r\n\r\n### Operating systems tested on:\r\n\r\nmacOS\n\n\u003c!-- gh-linked-prs --\u003e\n### Linked PRs\n* gh-124717\n* gh-124770\n* gh-126777\n* gh-127009\n\u003c!-- /gh-linked-prs --\u003e\n","author":{"url":"https://github.com/AlexWaygood","@type":"Person","name":"AlexWaygood"},"datePublished":"2024-09-26T00:02:10.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":25},"url":"https://github.com/124567/cpython/issues/124567"}