Increased build time with autosummary templates
#889
Comments
|
Thanks for opening this! Can you try one other thing:
The goal here would be to test whether this is related to
|
|
I cannot really say. Matplotlib doc build times are annoyingly slow (up to 12min). They vary quite strongly for local builds depending on clean/non-clean builds, the environment I use (likely versions of sphinx, sphinx-gallery, pydata-sphinx-theme, python version, ...), other unknown factors. There's too much noise in the data, so that I cannot say off the top of my head whether latest pydata-sphinx-theme makes a difference. Maybe @QuLogic has some statistics from CI runs? |
|
Thanks for the feedback. Interesting because for SciPy starting from 0.10 it's doubling our build time. |
|
Hey all - the latest state of getting around this is documented at this docs link: I don't think it's on the roadmap of this project to make any more technical changes to address this, unless the suggestions above really don't work for many people. |
|
I am sorry but I am a bit confused here as the issue is not linked to the TOC. Both NumPy and SciPy have seen their build time literally double making the CI go above the hour. Until this is resolve we are stuck with 0.9 and cannot update. If now you are saying this project won't do anything about the build issues with templates, then this should be documented and on our side we need to not use templates anymore so we can update the theme. |
|
I think (?) It is related to the sidebar TOC. The problem is that this theme nests all of it's sub-pages in the sidebar dropdowns. When there is an extension like autodoc that generates thousands of extra pages then it means that we now have |
|
No we limit to 2 levels on the ref pages. I will try again tomorrow to build with our newest version as the toc is even empty now. |
|
commenting here to be able to watch this thread. i'm going to test out templates as well and will see what happens to our build (our docs are tiny however compared to what @tupui is dealing with). |
|
Just a thought @tupui it would be helpful if you provided more context and a minimum reproducible example in the top comment. I know you have cross linked to some discussion in the PR, but it makes it easier to read and understand if it's all contained within the relevant issue. For example, what are autosummary templates? How can someone add them themselves to test it out? What's the simplest template that still causes a slowdown? One other thing that might be helpful. Check out this profile job in our noxfile: https://github.com/pydata/pydata-sphinx-theme/blob/main/noxfile.py#L122 You might be able to repurpose that for the scipy docs to see if we can pinpoint the function that is taking up all the extra time. |
|
I updated the linked PR to build with the latest version of the theme. It's still timing out and the build time goes above 40 mins. Sorry I won't spend more time repeating what I said elsewhere and on discord. I already gave a reproducer. Yes it's big as it's SciPy's doc (still, @drammock was able to reproduce), also, as I said in the linked issue, I could not reproduce with a smaller chunk of SciPy's doc. And as I said multiple times, I am not at all a web dev nor Sphinx expert. I just know my way around to make things work or adjust a bit according to my needs. I already spent a considerable amount of time on this issue and from all my report I think I showed enough effort...
I don't get what I would be supposed to do here. |
Sorry, I am just providing suggestions to make this issue easier for others to understand and take action on, in the hopes that it more quickly resolves your problem. I appreciate the scipy docs have this problem but I think a minimal reproducible example would be much more realistic for somebody to act on. I understand if you don't have time, maybe somebody else can figure out the minimal sphinx setup that reproduces this. We are all volunteers here, working on nights and weekends to maintain this theme, so the more complex something is, the lower the chance that people have time to get to it.
I think the relevant line is here: pydata-sphinx-theme/noxfile.py Lines 167 to 169 in 2d245c9 This uses py-spy to profile the build process of sphinx. It outputs an SVG that shows what things took the most time. You or somebody else could run this once with an old version of the theme, and once with a new version of the theme, and compare the two. |
We are all on the same wagon 😉 I don't think you need to use this argument with me... Hopefully the new CZI grant will help to mitigate that. I think I did my fair share by advocating for using this theme in all places and helped raised a few things and made PRs when I could and I did my best so far with this specific issue. But it's past 4 versions now that both SciPy and NumPy cannot use. Hence, I am not sure why you are not considering this to have a higher priority on the list. |
|
It's low on our priority list because we have the same problem as you do: we don't understand... and no other projects have reported such an increase (pandas, geopandas, bokeh, geodatacube). So without a reproducible example that's hard to tell if it's coming from us, autodoc, autosummary, Sphinx version etc... What I can offer is to do what @choldgraf just suggested tonight (while playing mario kart for low intervention supervision) and post the results here. I will also try to remove the templates to see if it's improving anything. See you in 5-6 hours |
|
Thanks for stopping by @12rambau. As of now I tested this on various versions of Sphinx (and other versions for various deps.) I could see every time that removing autosummary templates gives a 2x performance improvement (so back to previous build time.) |
|
I think an important thing to try is removing each template one by one, and seeing if a specific template is causing the slowdown. If you can pinpoint that then it'll be easier to debug what stuff it is calling. And yes unfortunately this issue is a combination of "small N of projects reporting, and I have no idea what's going on + the scipy docs build process is very confusing to me as well". |
|
I got swamped with work, I'll see what I can do this WE |
Discord? Whatever you said on Discord was in a server that we (or at least I) am not a member of. Please don't expect us to monitor Scipy's internal communication channels (even if they're public). I've just given another try at reproducing this. Here's what I did:
result: 5 autodoc-related warnings... @tupui are you also seeing those autodoc warnings? As for build time, Here's my environment: So as a SciPy outsider this seems like a |
|
Thank you @drammock for trying this out.
I was directly replying to Chris as we re-started this conversation on the Discord of Scientific Python.
I don't but we often have some discrepancy here between a local setup and CI. Not really a concern usually.
You are comparing Since you got it building, you can now more easily verify this by using
Merging |
|
@drammock here are some benchmarks I just did. The env is exactly the same for both, I only changed the theme's version. Using 0.9 ( Using 0.13.1 (my branch and I merged (In case that could indicate anything: the writing log of Sphinx are slightly slower, but most of the time is spend after that when nothing is printed.) |
I think that difference is not relevant unless comparing I'll see what else I can do when I can find time. Meanwhile please post your env. Differences in version of e.g. sphinx might matter here, so just saying "my env is the same across these benchmarks" doesn't help me figure out why my results differ from yours. |
|
Sure, here is my env (results above are with only changing the version of the theme.) Throughout the course of this issue, I (and NumPy folks) could reproduce (locally and in CI) on multiple versions of Sphinx, numpydoc, Python, etc. Conda Env |
|
@tupui here are my results. I cloned my scipy-dev environment (which has version 0.13.1 of the theme) and the only thing I changed was downgrading the theme to version 0.9.0. Before running the doc build in each env, I ran $ time python dev.py doc -j 6
real 7m45.241s
user 37m46.806s
sys 2m21.840s
$ mamba list pydata
# packages in environment at /opt/miniforge3/envs/spdev-pst9:
#
# Name Version Build Channel
pydata-sphinx-theme 0.9.0 pyhd8ed1ab_1 conda-forgethis had 3 warnings: one from within scipy coming from With 0.13.1 (below) there is just the one warning from within scipy, and the timings are basically the same: $ time python dev.py doc -j 6
real 7m20.661s
user 35m39.990s
sys 2m20.807s
$ mamba list pydata
# packages in environment at /opt/miniforge3/envs/scipy-dev:
#
# Name Version Build Channel
pydata-sphinx-theme 0.13.1 pyhd8ed1ab_0 conda-forgenote: the build time in my earlier comment from 2 days ago is not accurate: I was forgetting to do |
|
Very strange as it does not match the CI and my runs. I will try to reproduce your timing tomorrow from scratch. I am not sure about your cleaning. There is a clean in the makefile but I am not sure |
|
Well, it looks like it's doing what you'd expect: $ python dev.py doc clean
💻 ninja -C /opt/scipy/build
ninja: Entering directory `/opt/scipy/build'
[4/4] Generating scipy/generate-version with a custom command
Build OK
💻 meson install -C build --only-changed
Installing, see meson-install.log...
Installation OK
rm -rf build/* source/reference/generated <----- THIS LOOKS RIGHT, DOESN'T IT?...although to be honest I was surprised that |
|
Ok yes I confirm the cleaning part. This should be documented I will see to update the doc. I managed to reproduce your timings. Here is what is happening. Using the PR with 0.9 I get: This PR uses <nav class="bd-links" id="bd-docs-nav" aria-label="Main navigation">
<div class="bd-toc-item active">
{% if pagename.startswith("reference") %}
{{ generate_nav_html("sidebar", maxdepth=1, collapse=True, includehidden=True, titles_only=True) }}
{% else %}
{{ generate_nav_html("sidebar", maxdepth=2, collapse=True, includehidden=True, titles_only=True) }}
{% endif %}
</div>
</nav>This change was suggested by Chris and he approved the PR so I did not question it further. Adding back Now if I update the theme to 0.13.1 the timings are as follow:
Finally, staying on this configuration and removing the autosummary templates I get (this will make lot of warnings because we rely on them, but the doc still builds): (Note about the warning you see. It's due to a change introduced in Matplotlib 3.6) |
did you? Mine were:
If I'm reading you correctly, yours were:
so you're not testing the same thing as me, which makes it hard to say whether you've reproduced my timings or not. The next things I'll try (unless you suggest something else) are:
It will likely be mid-next-week before I can get back to this. |
Yes, and the listing you posted is correctly highlighting the hierarchy of timings (the 2x and roughly back to performances from 0.9). The discrepancy between your numbers and mine are not really relevant IMO as I would not say timing is very consistent. |
|
@tupui I come back to this issue as it's really enoying me. I tried in all the libs I'm working on that are using autosummary+ templates and I'm not able to reproduce your issue (I was expecting to see the same x2). I agree with @drammock there is something in your templates that is not behaving as expected. In a related PR you shared the following code (#878 (comment)): {{ fullname }}
{{ underline }}
.. currentmodule:: {{ module }}
.. autoclass:: {{ objname }}
:no-members:
:no-inherited-members:
:no-special-members:
{% block methods %}
.. HACK -- the point here is that we don't want this to appear in the output, but the autosummary should still generate the pages.
.. autosummary::
:toctree:
{% for item in all_methods %}
{%- if not item.startswith('_') or item in ['__call__', '__mul__', '__getitem__', '__len__'] %}
{{ name }}.{{ item }}
{%- endif -%}
{%- endfor %}
{% for item in inherited_members %}
{%- if item in ['__call__', '__mul__', '__getitem__', '__len__'] %}
{{ name }}.{{ item }}
{%- endif -%}
{%- endfor %}
{% endblock %}
{% block attributes %}
{% if attributes %}
.. HACK -- the point here is that we don't want this to appear in the output, but the autosummary should still generate the pages.
.. autosummary::
:toctree:
{% for item in all_attributes %}
{%- if not item.startswith('_') %}
{{ name }}.{{ item }}
{%- endif -%}
{%- endfor %}
{% endif %}
{% endblock %}Are you still using the same and could you share where it is ? (I want to see the diff with the normal one) |
|
Thank you for having a look @12rambau! I really appreciate the help here. You can find everything here: doc/source/_templates I am happy to hop in a call or anything if that can help. |
|
@tupui we can also look at this together in person sometime this week :) |
|
Definitely! 😃 |
|
You guys can meet in personn ? I'm jealous ;-) |
|
Yes we are at a Scientific Python summit :) https://scientific-python.org/summits/developer/2023/ |
|
ok small insight here:
One of my guess is that these toctree living in the python files were ignored by sphinx and are now taken into account when building the nav, making the build time explode. I need to continue investigate. |
|
@tupui can we chat somewhere else than in the issue tracker ? I don't want to flood others with my questions |
|
@12rambau I sent you an email, thanks 😃 |
|
hi folks! Just wanted to hop in here and mention that we have been facing a very similar issue with our project. We don't use the pydata sphinx theme, we have our own So far we've been experimenting with a few different solutions (at least for the short term), sharing the issue here in case you find it helpful: Qiskit/qiskit_sphinx_theme#328 |
|
Thank you @javabster! I am happy to read that we are not the only one 😅 From what I read in the linked issue, you seem to also have problems with the sidebar. That might be linked as I could also experiment there and saw large performance drop playing with that scipy/scipy#18604 |
|
To recap our plan for That should get build times and HTML page sizes "acceptable enough" for prod builds. For dev builds (e.g. CI), we will use |
|
Interesting 👍 thank you for sharing that. |
|
Hi all, we've been seing the same issue over at sunpy. I've done some profiling, and tracked the slowdown to these lines: pydata-sphinx-theme/src/pydata_sphinx_theme/__init__.py Lines 223 to 233 in c1befa8 
What seems to be happening is any custom templates are being rendered for every page, just for the purpose of checking if they're empty. For sunpy, as can be seen above in the profiling graph, this almost doubles the total build time. If we switch to the vanilla So it seems like the way to approach this is see if there's a way to speed up |
|
Thank you @dstansby for the info! I'd hoped to revisit this last week (but ran out of time) and now I'm on holiday, but will pick up the baton in about a week when I'm back at my desk |
|
I tried a naive attempt at speeding up the SciPy doc build (simply commenting out the line that calls @dstansby can you share how exactly you set up the profiling? Decorating |
|
I did something like |
|
And FWIW the slow code seems to have come in via #1115 |
|
(lack of) progress report: for the scipy docs, there is almost no difference in build time between running with or without (I confirmed in snakeviz that |
|
I'm reopening the issue until @tupui confirms with v0.15.0rc0 that this fix is effectively solving the scipy issue in their CI |
|
I will do that today and let you know 😃 |
|
Seems to be working!!! Thanks @drammock for tracking this one down. I will also post on SciPy's PR. |
|
I'll release 0.15 then and close this issue, thanks for staying around ! |
|
this patch is now available on pypi in v0.15.1 |
In some cases, using
autosummarytemplates causes a significant increase in build time. This is particularly true for the scipy and nump docs (link to autosummary templates scipy uses).I have verified this using this version of SciPy scipy/scipy#16660 and built the documentation on
mainand also with changes from #878. In both cases I run with and without templates.originally discussed in #878,
The text was updated successfully, but these errors were encountered: