CMS takes too long to generate web.adblockplus.org

[juliandoucette]

Environment

Macbook Pro

How to reproduce

1. clone web.adblockplus.org
2. run cms.bin.generate_static_pages

Observed behaviour

This script takes a long time to run.

Expected behaviour

This script should not take a long time to run.

[juliandoucette]

I know this opinionated... But I also think it's obvious and should be documented somewhere :D

[kvas]

I agree that it takes too long. I wonder if it's the CMS or the global functions of web.adblockplus.org (that download stuff from the internet) that make it slow. Have you looked into it?

[juliandoucette]

Have you looked into it?

No.

[jsonesen]

I haven't looked into this either but I have noticed it is rather slow. I reckon it is the network requests holding up the execution since as far as operations go they tend to be the slowest, then if you have lots of them running sequentially it adds up. There is also the mercurial calls.

[kvas]

Profile: generate_static_pages()

[kvas]

Profile: converters.py: call

[kvas]

I've spent some hours profiling the CMS today. First of all, networks requests are not the main reason for slow rendering in case of www.adblockplus.org. Mocking them out brings the time down to 1m50s (from 1m54s), which is fairly small. So what can we do?

First easy option is running the rendering job with ​PyPy (I used version 5.8.0) instead of regular Python. It finishes in 1m20s, which is about 30% faster. This is still fairly slow, so I've run the rendering under a profiler and started looking at what took most of the time. Here's the visualisation of the top level:

Here we can see that the time is split between utils.py:process_pageand utils.py:get_page_params. process_page also calls get_page_params inside of it and each of them calls converters.py:Converter:__call__, which is where most of the time is spent. What's going on here?

What happens is that CMS calls Converter:__call__ twice for each page-locale combination: first time to determine if there's enough translation material for it and then again to render it (the second call doesn't happen if the first one determined that the page is not translated enough). In addition to that, the second pass is also followed by Converter:__call__ for the template of the page. As we can see from the picture above, most of the time is spent in Converter:__call__. So what's going on inside of it?

Of the time spent inside __call__ about 20% is spent inside of resolve_includes (purple block), which is mostly regexp substitution with some functions called inside. The rest is get_html, which is different for different converters. The biggest chunk of time is get_html of TemplateConverter (>50%), which mostly compiles Jinja templates. The remaining blocks are get_html of RawConverter and MarkdownConverter, which mostly spend time on localization.

From this investigation it seems like significant optimization is possible by avoiding recompilation of templates and possibly caching some other things here and there to avoid recomputing the same values multiple times. This is not going to be too easy, but right now my estimate is that it's possible to at least double the performance of CMS by spending less than a week on more detailed investigation / coding.

[juliandoucette]

Thanks kvas :) - I look forward to it.

[abpbot]

A commit referencing this issue has landed:
​Issue 5601 - Speed up static generation