Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cache intermediate NJK template compiles #1529

Merged
merged 10 commits into from
Feb 6, 2021
Merged

Conversation

slightlyoff
Copy link
Contributor

@slightlyoff slightlyoff commented Nov 24, 2020

TL;DR: this patch speeds up my local 11ty-work-only build steps by ~50%

I noticed that running 11ty from upstream is much slower than the 0.11.x branch, which surprised me given some of the work I put in earlier this year. I don't have a root cause analysis, but it got annoying so I decided to see if I couldn't speed things up in my local workflow. This patch picks one of the low-hanging fruit I mused at back in May, caching intermediate template compiles after some profiling showed that repeated application of the same templates across many data files was causing NJK compilation to show up as heavy in my local blog project.

The benefits here are NJK specific (sorry, other template engines!) and probably brittle. Feedback on the patch appreciated.

Before (11ty/eleventy HEAD)

slightlyoff@penguin:~/projects/infrequently$ time (npm run rebuild)

> infrequently.org@ rebuild /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && REBUILD=true npx eleventy

Writing build/feed/feed.xml from ./_posts/feed.njk
...
Writing build/2018/09/the-developer-experience-bait-and-switch/comments.html from ./_posts/2018/09/the-developer-experience-bait-and-switch/comments.md (njk)
Copied 29 files / Wrote 1182 files in 11.76 seconds (9.9ms each, v1.0.0-beta.0)

real    0m13.698s
user    0m15.017s
sys     0m1.503s

After (NJK template caching branch)

slightlyoff@penguin:~/projects/infrequently$ time (npm run rebuild)

> infrequently.org@ rebuild /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && REBUILD=true npx eleventy

Writing build/feed/feed.xml from ./_posts/feed.njk
...
Writing build/2018/09/the-developer-experience-bait-and-switch/comments.html from ./_posts/2018/09/the-developer-experience-bait-and-switch/comments.md (njk)
Copied 29 files / Wrote 1182 files in 5.13 seconds (4.3ms each, v1.0.0-beta.0)

real    0m7.025s
user    0m7.620s
sys     0m1.228s

Copy link
Contributor

@Ryuno-Ki Ryuno-Ki left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From what I understood, you're basically applying a memoization by looking at the passed extensions and template blocks.

There are some parts, where I think, adding a bit more documentation and picking better variable names could go a long way.

src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
let ae = NunjucksLib.Environment.prototype.addExtension;
NunjucksLib.Environment.prototype.addExtension = function (...args) {
let e = args[1];
e.__id = inc();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this collision proof? Can it happen that the same increment gets assigned to different __ids? (Perhaps worth to generate a proper UUID here?)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is collision proof AFAICT. The 11ty heap lives longer than the invocation of any (and every) sub-template engine, and all extensions are funneled through the Environment's addExtension method at the end.

src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
src/Engines/Nunjucks.js Show resolved Hide resolved
src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
src/Engines/Nunjucks.js Outdated Show resolved Hide resolved
@nhoizey
Copy link
Contributor

nhoizey commented Nov 24, 2020

My test with this PR:

Eleventy v0.11.1

Copied 882 files / Wrote 2188 files in 365.20 seconds (166.9ms each, v0.11.1)

Eleventy HEAD

Copied 882 files / Wrote 2188 files in 351.99 seconds (160.9ms each, v1.0.0-beta.0)

With this PR #1529

Copied 882 files / Wrote 2188 files in 346.38 seconds (158.3ms each, v1.0.0-beta.0)

@slightlyoff
Copy link
Contributor Author

slightlyoff commented Nov 24, 2020

My test with this PR:

Thank you for testing! Were the results correct? No mangled content?

Copied 882 files / Wrote 2188 files in 346.38 seconds (158.3ms each, v1.0.0-beta.0)

These are very, very slow build times. Is the repo open source by any chance? Can you say more about your build process and hardware/OS?

@nhoizey
Copy link
Contributor

nhoizey commented Nov 24, 2020

Were the results correct? No mangled content?

Yes, everything is fine. 👍

These are very, very slow build times.

Indeed, it is 10x what I had not so long ago, because of a very complicated layout I made for my archives, as I explained here: https://nicolas-hoizey.com/articles/2020/10/26/enhancing-archives-navigation-step-1/

The layout has many loops and tests to deal with yearly and monthly archives of 4 different collections:
https://github.com/nhoizey/nicolas-hoizey.com/blob/master/src/_layouts/archives.njk

I know that I should be able to enhance it with better collections preparation:
https://github.com/nhoizey/nicolas-hoizey.com/blob/master/src/_11ty/collections/years-and-months.js

Is the repo open source by any chance?

Yes: https://github.com/nhoizey/nicolas-hoizey.com/

If you try to run a build, you will need a few private environment variables, I don't know if I can easily make it work without them. 🤔

Can you say more about your build process and hardware/OS?

As you will see in my package.json, I build CSS from Sass with CLI Dart Sass and PostCSS, JavaScript (both ES6 and IIFE) with CLI Rollup, so Eleventy doesn't have to build these assets. The build time I gave were just for Eleventy.

I'm running this on a MacBook Pro 13" 2018 Core i5 with 16 GB RAM, on macOS Big Sur 11.0.1. Big Sur didn't change my built times.

HTH

@mathiasbynens
Copy link

mathiasbynens commented Nov 25, 2020

I’ve tested this against v8.dev @ d3917ab758052a2b7168e5427cf6404f9501fd90. Here’s the results.

With eleventy v0.11.1:

Copied 627 files / Wrote 266 files in 2.33 seconds (8.8ms each, v0.11.1)

With latest eleventy HEAD (9042341):

Copied 627 files / Wrote 266 files in 2.08 seconds (7.8ms each, v1.0.0-beta.0)

With this patch:

Copied 627 files / Wrote 266 files in 1.84 seconds (6.9ms each, v1.0.0-beta.0)

I’ve confirmed there’s no difference in output — the generated files are bit-by-bit identical in all cases.

@nhoizey
Copy link
Contributor

nhoizey commented Nov 25, 2020

With HTML minification disabled (thanks @slightlyoff !), my tests now give these build times (3 builds for each):

With Eleventy v0.11.1:

Copied 882 files / Wrote 2188 files in 37.66 seconds (17.2ms each, v0.11.1)
Copied 882 files / Wrote 2188 files in 38.48 seconds (17.6ms each, v0.11.1)
Copied 882 files / Wrote 2188 files in 39.49 seconds (18.0ms each, v0.11.1)

With Eleventy HEAD (much slower indeed):

Copied 882 files / Wrote 2188 files in 60.00 seconds (27.4ms each, v1.0.0-beta.0)
Copied 882 files / Wrote 2188 files in 52.75 seconds (24.1ms each, v1.0.0-beta.0)
Copied 882 files / Wrote 2188 files in 55.51 seconds (25.4ms each, v1.0.0-beta.0)

With this PR #1529:

Copied 882 files / Wrote 2188 files in 35.01 seconds (16.0ms each, v1.0.0-beta.0)
Copied 882 files / Wrote 2188 files in 33.09 seconds (15.1ms each, v1.0.0-beta.0)
Copied 882 files / Wrote 2188 files in 37.16 seconds (17.0ms each, v1.0.0-beta.0)

@khawkins98
Copy link

Really interesting.

Wrote 162 files in 17.72 seconds (109.4ms each, v0.11.1)

Wrote 162 files in 8.20 seconds (50.6ms each, v1.0.0-beta.0)
Wrote 162 files in 7.72 seconds (47.7ms each, v1.0.0-beta.0)
Wrote 162 files in 8.79 seconds (54.3ms each, v1.0.0-beta.0)

Wrote 162 files in 5.37 seconds (33.1ms each, v1.0.0-beta.0+patch)
Wrote 162 files in 5.26 seconds (32.5ms each, v1.0.0-beta.0+patch)
Wrote 162 files in 5.10 seconds (31.5ms each, v1.0.0-beta.0+patch)

Likely due to our use case, head is still faster than 0.11.1. (We have a fairly exotic setup of 11ty where we pass in a nunjucks environment that 11ty then extends.)

Behaviour is still as expected. 👍

@slightlyoff
Copy link
Contributor Author

slightlyoff commented Dec 3, 2020

Thanks everyone who has been testing this out! I've rev'd the patch with some additional potential speedups. I might not need to go spelunking to wire up cache invalidation under --watch to re-enable Nunjucks internal caching. If folks could update and verify the latest version isn't breaking them, that would be swell.

For comparison, vs. original with default logging (which is slow and adds a lot of variance):

slightlyoff@penguin:~/projects/infrequently$ time (npm run rebuild-debug)

> infrequently.org@ rebuild-debug /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && REBUILD=true npx eleventy

Writing build/feed/feed.xml from ./_posts/feed.njk
...
Copied 29 files / Wrote 1182 files in 4.61 seconds (3.9ms each, v1.0.0-beta.0)

real    0m6.201s
user    0m6.743s
sys     0m1.258s

Here's current HEAD with debugging output removed:

slightlyoff@penguin:~/projects/infrequently$ npm run rebuild

> infrequently.org@ rebuild /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && DEBUG=-* REBUILD=true npx eleventy

Copied 29 files / Wrote 1182 files in 10.67 seconds (9.0ms each, v1.0.0-beta.0)

Here's 0.11.1:

slightlyoff@penguin:~/projects/infrequently$ npm run rebuild

> infrequently.org@ rebuild /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && DEBUG=-* REBUILD=true npx eleventy

Copied 29 files / Wrote 1182 files in 6.14 seconds (5.2ms each, v0.11.1)

And the same for the new branch:

slightlyoff@penguin:~/projects/infrequently$ npm run rebuild

> infrequently.org@ rebuild /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && DEBUG=-* REBUILD=true npx eleventy

Copied 29 files / Wrote 1182 files in 4.15 seconds (3.5ms each, v1.0.0-beta.0)

@nhoizey
Copy link
Contributor

nhoizey commented Dec 3, 2020

Here are my new results:

With Eleventy v0.11.1

Copied 887 files / Wrote 2312 files in 46.34 seconds (20.0ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 45.50 seconds (19.7ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 47.34 seconds (20.5ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 46.05 seconds (19.9ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 45.50 seconds (19.7ms each, v0.11.1)

With Eleventy HEAD

Copied 887 files / Wrote 2312 files in 71.30 seconds (30.8ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 66.44 seconds (28.7ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 65.49 seconds (28.3ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 67.03 seconds (29.0ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 67.40 seconds (29.2ms each, v1.0.0-beta.0)

With this PR

Copied 887 files / Wrote 2312 files in 51.16 seconds (22.1ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 48.57 seconds (21.0ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 49.94 seconds (21.6ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 50.18 seconds (21.7ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 50.41 seconds (21.8ms each, v1.0.0-beta.0)

And because I know my responsive images transform is really slow (I have a lot of pages with a lot of images), I also ran Eleventy without it:

With Eleventy v0.11.1

Copied 887 files / Wrote 2312 files in 31.71 seconds (13.7ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 25.70 seconds (11.1ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 25.21 seconds (10.9ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 25.63 seconds (11.1ms each, v0.11.1)
Copied 887 files / Wrote 2312 files in 25.77 seconds (11.1ms each, v0.11.1)

With Eleventy HEAD

Copied 887 files / Wrote 2312 files in 40.85 seconds (17.7ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 40.58 seconds (17.6ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 41.89 seconds (18.1ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 40.33 seconds (17.4ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 40.56 seconds (17.5ms each, v1.0.0-beta.0)

With this PR

Copied 887 files / Wrote 2312 files in 18.80 seconds (8.1ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 19.14 seconds (8.3ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 19.46 seconds (8.4ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 18.64 seconds (8.1ms each, v1.0.0-beta.0)
Copied 887 files / Wrote 2312 files in 19.70 seconds (8.5ms each, v1.0.0-beta.0)

@khawkins98
Copy link

Still working well. This time with a smaller project that also inherits a pre-built Nunjucks environment.

With Eleventy v0.11.1

Copied 103 files / Wrote 33 files in 1.08 seconds (32.7ms each, v0.11.1)
Copied 103 files / Wrote 33 files in 1.04 seconds (31.5ms each, v0.11.1)
Copied 103 files / Wrote 33 files in 1.14 seconds (34.5ms each, v0.11.1)

With Eleventy HEAD

Copied 103 files / Wrote 33 files in 0.92 seconds (27.9ms each, v1.0.0-beta.0)
Copied 103 files / Wrote 33 files in 1.08 seconds (32.7ms each, v1.0.0-beta.0)
Copied 103 files / Wrote 33 files in 0.85 seconds (25.8ms each, v1.0.0-beta.0)

With this PR

Copied 103 files / Wrote 33 files in 0.83 seconds (25.2ms each, v1.0.0-beta.0+patch)
Copied 103 files / Wrote 33 files in 0.87 seconds (26.4ms each, v1.0.0-beta.0+patch)
Copied 103 files / Wrote 33 files in 0.75 seconds (22.7ms each, v1.0.0-beta.0+patch)

@slightlyoff
Copy link
Contributor Author

slightlyoff commented Dec 4, 2020

One final (I hope!) functional update now re-enables NJK's internal caches which speed things up a little bit more for me. Previous timing was:

Copied 29 files / Wrote 1182 files in 4.15 seconds (3.5ms each, v1.0.0-beta.0)

And the new result is:

slightlyoff@penguin:~/projects/infrequently$ npm run rebuild

> infrequently.org@ rebuild /home/slightlyoff/projects/infrequently
> unset CACHE_BUST && DEBUG=-* REBUILD=true npx eleventy

Copied 29 files / Wrote 1182 files in 3.53 seconds (3.0ms each, v1.0.0-beta.0)

...or another 15% faster. I expect the potential speedup from this change is highly I/O-performance dependent, as its primary effect is to keep NJK from going to disk as often.

Versus HEAD, it's now 66% faster for me locally rebuilding and 40% faster than 0.11.1. Probably enough for now.

@zachleat zachleat merged commit 0cf3fd1 into 11ty:master Feb 6, 2021
@zachleat
Copy link
Member

zachleat commented Feb 6, 2021

This is excellent—thank you! Will ship with 1.0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants