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

Eleventy 3.0.0 export performance regression #3473

Open
j9t opened this issue Oct 4, 2024 · 17 comments
Open

Eleventy 3.0.0 export performance regression #3473

j9t opened this issue Oct 4, 2024 · 17 comments

Comments

@j9t
Copy link

j9t commented Oct 4, 2024

Operating system

macOS 14.6.1

Eleventy

3.0.0

Describe the bug

Just kicking this off as an observation, I’m consistently observing a significant performance regression after upgrading from Eleventy 2.0.1 to 3.0.0.

With no other changes, processing ~10,000 files resulting in ~1,500 output files took ~45 seconds before, and ~65 seconds now.

I can make access to the private repo available if of interest, but do also submit this to give other Eleventy users a chance to collect similar observations, as well as to comment if this is a known issue or perhaps being worked on.

Reproduction steps

(As described.)

Expected behavior

Given how important performance is, export time stays roughly the same or improves.

Reproduction URL

No response

Screenshots

No response

@j9t j9t changed the title Export performance regression Eleventy 3.0.0 export performance regression Oct 4, 2024
@rothsandro
Copy link

rothsandro commented Oct 5, 2024

I'm currently migrating Eleventy Notes from v2.0.1 to v3. The template has just 45 files but the build time increases from ~0.35s to ~0.64s. That's still pretty fast of course, but I didn't expect that the build time increases with the update.

Edit: I now tested Eleventy in a new project without any config on 10k markdown files and v3 is ~1s slower than v2.

@michael-proulx
Copy link

We're processing approximately 5,000 files. On 11ty 2.0.1, it took 72.95 seconds (14.7ms per file), but on 11ty 3.0.0, it takes 186.98 seconds (37.5ms per file), nearly tripling the build time.

I plan to start a fresh project to investigate further and determine what is impacting performance.

@Ryuno-Ki
Copy link
Contributor

Ryuno-Ki commented Oct 9, 2024

Could you also log Performance Metrics?

That could help understand the specific part being slower.

@michael-proulx
Copy link

@Ryuno-Ki

Won't add the full log (~16,000 lines), but here is the ones that seem to use alot of resources.
The md files are mostly 0ms to 2ms each

The debug took 110.76 seconds (22.2ms each)

Eleventy:Benchmark Benchmark      6ms   0%  5692× (Configuration) "@11ty/eleventy-bundle" Transform +0ms
Eleventy:Benchmark Benchmark     22ms   0%  5692× (Configuration) "@11ty/eleventy/html-transformer" Transform +1ms
Eleventy:Benchmark Benchmark     27ms   0%     1× (Configuration) "postcss" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      3ms   0% 17966× (Configuration) "if" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      5ms   0%  7192× (Configuration) "docLink" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      2ms   0%  7196× (Configuration) "getProjectFromFilePathStem" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      2ms   0%  7196× (Configuration) "getLangFromFilePathStem" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      3ms   0% 13575× (Configuration) "localized" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      1ms   0%  2074× (Configuration) "localized" Nunjucks Filter +0ms
Eleventy:Benchmark Benchmark      3ms   0%  7190× (Configuration) "localizedUrl" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      1ms   0%  2784× (Configuration) "localizedUrl" Nunjucks Filter +0ms
Eleventy:Benchmark Benchmark    190ms   0%  3594× (Configuration) "toc" Liquid Filter +1ms
Eleventy:Benchmark Benchmark     74ms   0%  1391× (Configuration) "toc" Nunjucks Filter +0ms
Eleventy:Benchmark Benchmark     15ms   0% 111287× (Configuration) "findFirstChildrenUrlTree" Nunjucks Filter +0ms
Eleventy:Benchmark Benchmark      2ms   0%  1391× (Configuration) "filterTree" Nunjucks Filter +0ms
Eleventy:Benchmark Benchmark    244ms   0% 112678× (Configuration) "sortTree" Nunjucks Filter +0ms
Eleventy:Benchmark Benchmark    124ms   0%  3516× (Configuration) "sidebar" Liquid Shortcode +0ms
Eleventy:Benchmark Benchmark      6ms   0%  3594× (Configuration) "gTab" Liquid Filter +0ms
Eleventy:Benchmark Benchmark      1ms   0%   912× (Configuration) "var" Liquid Shortcode +0ms
Eleventy:Benchmark Benchmark      0ms   0%   264× (Configuration) "youtube" Liquid Shortcode +0ms
Eleventy:Benchmark Benchmark     59ms   0%  4479× (Configuration) "snippet" Liquid Paired Shortcode +0ms
Eleventy:Benchmark Benchmark     74ms   0%   605× (Configuration) "gTab" Liquid Paired Shortcode +0ms
Eleventy:Benchmark Benchmark      2ms   0%     8× (Aggregate) Configuration addPlugin +4ms
Eleventy:Benchmark Benchmark      1ms   0%     1× (Aggregate) Processing plugins in config +0ms
Eleventy:Benchmark Benchmark    114ms   0%     1× (Aggregate) Searching the file system (templates) +0ms
Eleventy:Benchmark Benchmark    715ms   1%  4239× (Aggregate) Data File +0ms
Eleventy:Benchmark Benchmark     43ms   0%     1× (Aggregate) Searching the file system (data) +0ms
Eleventy:Benchmark Benchmark     59ms   0%     8× (Aggregate) Passthrough Copy File +0ms
Eleventy:Benchmark Benchmark   5225ms   5%  5697× (Aggregate) Template Read +0ms
Eleventy:Benchmark Benchmark      0ms   0%    17× (Aggregate) Engine (scss) Get Data From File (Function) +0ms
Eleventy:Benchmark Benchmark      0ms   0%    20× (Aggregate) (count) getOutputLocations +0ms
Eleventy:Benchmark Benchmark      0ms   0% 11344× (Aggregate) (count) getOutputHref +0ms
Eleventy:Benchmark Benchmark      0ms   0% 11344× (Aggregate) (count) getOutputPath +0ms
Eleventy:Benchmark Benchmark      0ms   0% 27444× (Aggregate) (count) Template Compile Cache Miss +0ms
Eleventy:Benchmark Benchmark    247ms   0% 16756× (Aggregate) Template Compile Computed Data +0ms
Eleventy:Benchmark Benchmark      1ms   0%     2× (Aggregate) > Compile Computed Data > ./docs/content/de/kb/index.html +0ms
Eleventy:Benchmark Benchmark   2243ms   2% 49258× (Aggregate) Render +0ms
Eleventy:Benchmark Benchmark      1ms   0%     4× (Aggregate) > Render Computed Data > ./docs/content/de/kb/index.html +1ms
Eleventy:Benchmark Benchmark     78ms   0%  4991× (Aggregate) Template Compile Permalink +0ms
Eleventy:Benchmark Benchmark      0ms   0%     2× (Aggregate) > Render Permalink > ./docs/content/de/kb/index.html +0ms
Eleventy:Benchmark Benchmark      0ms   0% 21835× (Aggregate) (count) Template Compile Cache Hit +0ms
Eleventy:Benchmark Benchmark      0ms   0%     3× (Aggregate) > Compile Computed Data > ./docs/content/fr/dgw/index.md +0ms
...
Eleventy:Benchmark Benchmark      2ms   0%     1× (Aggregate) > Render > ./docs/en/rdm/mac/user-interface/content-area/dashboard/dashboard-tabs/macros-scripts-tools.md +0ms
Eleventy:Benchmark Benchmark     15ms   0%     1× (Aggregate) > Compile > ./docs/_includes/layouts/markdown.liquid +0ms
Eleventy:Benchmark Benchmark     15ms   0%     1× (Aggregate) > Compile > ./docs/_includes/layouts/base.njk +0ms
Eleventy:Benchmark Benchmark     15ms   0%     1× (Aggregate) > Compile > ./docs/_includes/layouts/home.liquid +0ms
Eleventy:Benchmark Benchmark     14ms   0%     1× (Aggregate) > Compile > ./docs/_includes/layouts/markdown.njk +1ms
Eleventy:Benchmark Benchmark   1124ms   1%  4991× (Aggregate) Template make parent directory +0ms
Eleventy:Benchmark Benchmark  15159ms  14%  4991× (Aggregate) Template Write +0ms
Eleventy:Benchmark Benchmark    583ms   1%     1× (Data) `./docs/de/de.11tydata.js` +0ms
Eleventy:Benchmark Benchmark    583ms   1%  1374× (Data) `./docs/en/en.11tydata.js` +0ms
Eleventy:Benchmark Benchmark    583ms   1%   700× (Data) `./docs/fr/fr.11tydata.js` +0ms
Eleventy:Benchmark Benchmark     45ms   0%     1× (Data) `./docs/de/rdm/z-parking/z-parking.11tydata.js` +0ms
Eleventy:Benchmark Benchmark     44ms   0%   692× (Data) `./docs/en/rdm/mac/mac.11tydata.js` +0ms
Eleventy:Benchmark Benchmark     44ms   0%   682× (Data) `./docs/en/rdm/z-parking/z-parking.11tydata.js` +0ms
Eleventy:Benchmark Benchmark     15ms   0%   699× (Data) `./docs/fr/rdm/mac/mac.11tydata.js` +0ms
Eleventy:Benchmark Benchmark     14ms   0%     1× (Data) `./docs/_data/config.js` +0ms
Eleventy:Benchmark Benchmark      6ms   0%    84× (Data) `./docs/en/rdm/z-parking/kb/z-parking/z-parking.11tydata.js` +0ms
Eleventy:Benchmark Benchmark      2ms   0%     1× (Data) `./docs/_data/de.js` +1ms
Eleventy:Benchmark Benchmark      2ms   0%     1× (Data) `./docs/_data/en.js` +0ms
Eleventy:Benchmark Benchmark      1ms   0%     1× (Data) `./docs/_data/env.js` +0ms
Eleventy:Benchmark Benchmark      2ms   0%     1× (Data) `./docs/_data/fr.js` +0ms
Eleventy:Benchmark Benchmark     74ms   0%     1× (Data) `./docs/_data/icons.js` +0ms

@Ryuno-Ki
Copy link
Contributor

Ryuno-Ki commented Oct 9, 2024

Thanks!

Looks I/O bound (Template Read and Write)

@j9t
Copy link
Author

j9t commented Oct 9, 2024

Attaching my own log. A bit faster on this run (55 seconds), but slower than pre-Eleventy 3.0.0.

log.txt

@Ryuno-Ki
Copy link
Contributor

Ryuno-Ki commented Oct 9, 2024

Thanks.

I spotted:

  Eleventy:Benchmark Benchmark   5694ms  10% 234896× (Configuration) "url" Nunjucks Filter +1ms
  Eleventy:Benchmark Benchmark   6434ms  12% 12410× (Configuration) "htmlmin" Transform +0ms

Unrelated (see NaN):

  Eleventy:Benchmark Benchmark     67ms NaN%     1× (Watch) Start up --watch +68ms
  Eleventy:Benchmark Benchmark     64ms NaN%     1× (Watch) Watching JavaScript Dependencies (disable with `eleventyConfig.setWatchJavaScriptDependencies(false)`) +0ms

@michael-proulx
Copy link

I stripped everything from my project, leaving only the markdown files. I also created empty shortcodes to avoid refactoring them.

Below is a comparison between 11ty 2.0.1 and 3.0.0 for generating files from markdown, both using the same stripped-down code with the debug variable.

image

The results below are from five builds. The first build needed to generate the output folder.

image

@j9t
Copy link
Author

j9t commented Oct 14, 2024

  Eleventy:Benchmark Benchmark   5694ms  10% 234896× (Configuration) "url" Nunjucks Filter +1ms

Side note, I took this to investigate and noticed I don’t need url. Thanks!

(That’s not to distract from the issue though—Eleventy performance did degrade after the upgrade.)

@zachleat
Copy link
Member

Related: https://github.com/11ty/eleventy-benchmark

@zachleat
Copy link
Member

zachleat commented Oct 18, 2024

Spent a little time on this one in PR #3493

Bench results:

---------------------------------------------------------
Eleventy Benchmark (Node v20.18.0, 2500 templates each)
---------------------------------------------------------
Eleventy 3.0.0                                        
---------------------------------------------------------
.md: ..... 5 runs:            
* Median: 1.95 seconds
* Median per template: 780 µs

.11ty.js: ..... 5 runs:       
* Median: 1.73 seconds
* Median per template: 692 µs

---------------------------------------------------------
Eleventy 3.0.1-alpha.1                                        
---------------------------------------------------------
.md: ..... 5 runs:            
* Median: 1.62 seconds (-17%)
* Median per template: 648 µs (-17%)

.11ty.js: ..... 5 runs:       
* Median: 1.39 seconds (-20%)
* Median per template: 556 µs (-20%)

Worth nothing that there is extra overhead that came with ESM support and the ESM loader built into Node.js that is just a bit slower overall, unfortunately—but improvements are being made!

@zachleat zachleat added this to the Eleventy 3.0.1 milestone Oct 18, 2024
@zachleat
Copy link
Member

For other folks, it’d be very helpful to get a .cpuprofile for your build so I can analyze it a bit more clearly:

node --cpu-prof ./node_modules/.bin/eleventy --quiet

I will also accept these via email if you don’t want to attach them to the issue: [email protected]

@michael-proulx
Copy link

Hey @zachleat,

Thanks for your time on this one!

Your command didn't work on my side, but using this one works

node --cpu-prof ./node_modules/@11ty/eleventy/cmd.cjs --quiet

It has generated 2 files:
CPU.20241018.182203.13640.0.001.cpuprofile
CPU.20241018.182203.13640.1.002.cpuprofile

@zachleat
Copy link
Member

Hey @michael-proulx your profiles revealed the same slowdowns eliminated in #3493! Thank you for uploading! Looks like you’ll save about 1.8s on your build with those improvements

image

@nhoizey
Copy link
Contributor

nhoizey commented Oct 28, 2024

I also face a big increase of my build time with Eleventy 3 (but it's not the only change in my project, and issues with time limit on Netlify: https://mamot.fr/@nhoizey/113378722980419766

I ran the command to get the .cpuprofile files, I hope it can help:
CPU.20241028.173615.72924.0.001.cpuprofile
CPU.20241028.173616.72924.1.002.cpuprofile

I guess I should use getFilteredByGlob a little less…

CleanShot 2024-10-28 at 17 50 13@2x

@tomayac
Copy link

tomayac commented Nov 4, 2024

I have a strange issue where locally on my MacBook Pro (M1), it builds my blog in ~9s, but on my VPS, it starts fast, but then slows down to a halt the more pages it writes, until eventually it gets killed.

  • Server:
    […Snip…]
    [11ty] Writing ./_site/2023/04/18/getting-my-domain-tomayac-de-back/index.html from ./posts/2023/04/getting-my-domain-tomayac-de-back.md (liquid)
    [11ty] Writing ./_site/2023/06/07/web-apps-on-macos-sonoma-14-beta/index.html from ./posts/2023/06/web-apps-on-macos-sonoma-14-beta.md (liquid)
    [11ty] Writing ./_site/2023/09/25/w3c-tpac-2023-trip-report/index.html from ./posts/2023/09/w3c-tpac-2023-trip-report.md (liquid)
    [11ty] Writing ./_site/2024/01/17/a-wasm-new-year/index.html from ./posts/2024/01/a-wasm-new-year.md (liquid)
    [11ty] Writing ./_site/2024/02/lenovo-p27h-20-randomly-turns-off/index.html from ./posts/2024/02/lenovo-p27h-20-randomly-turns-off.md (liquid)
    [11ty] Writing ./_site/2024/02/28/so-what-exactly-did-apple-break-in-the-eu/index.html from ./posts/2024/02/so-what-exactly-did-apple-break-in-the-eu.md (liquid)
    Killed
    
  • Client:
    [Snip…]
    [11ty] Writing ./_site/2011/10/20/next-generation-web-services-practices-nwesp-100210/index.html from ./posts/2011/2011-10-20_next-generation-web-services-practices-nwesp.html (njk)
    [11ty] Writing ./_site/2008/12/18/death-prevails-hackneyed-235248/index.html from ./posts/2008/2008-12-18_death-prevails-hackneyed.html (njk)
    [11ty] Writing ./_site/2014/04/02/telling-breaking-news-stories-from-wikipedia-with-social-multimedia-a-case-study-of-the-2014-winter-olympics-085709/index.html from ./posts/2014/2014-04-02_telling-breaking-news-stories-from-wikipedia-with-social-multimedia-a-case-study-of-the-2014-winter-olympics.html (njk)
    [11ty] Writing ./_site/2019/08/15/a-quick-look-at-wechats-mini-programs/index.html from ./posts/2019/2019-08-15_a-quick-look-at-wechats-mini-programs.md (liquid)
    [11ty] Writing ./_site/2023/02/23/cross-platform-software-frameworks/index.html from ./posts/2023/02/cross-platform-software-frameworks.md (liquid)
    [11ty/eleventy-img] 1136 images optimized (1136 cached)
    [11ty] Benchmark   2306ms  23%   573× (Configuration) "htmlmin" Transform
    [11ty] Copied 374 Wrote 573 files in 9.90 seconds (17.3ms each, v3.0.0)
    

If I run top on the server, I can see that it's almost max'ed out on its RAM (0.5GB only, I'm cheap, and on a really old contract).

@tomayac
Copy link

tomayac commented Nov 4, 2024

Server:

  Eleventy Total passthrough copy aggregate size: '60.97 MB' +9m
[11ty] Copied 374 Wrote 573 files in 565.47 seconds (986.9ms each, v3.0.0)
  Eleventy Finished. +28ms
  Eleventy
  Eleventy Have a suggestion/feature request/feedback? Feeling frustrated? I want to hear it!
  Eleventy Open an issue: https://github.com/11ty/eleventy/issues/new +0ms

Client:

Eleventy Total passthrough copy aggregate size: '60.97 MB' +9s
[11ty] Copied 374 Wrote 573 files in 9.62 seconds (16.8ms each, v3.0.0)
  Eleventy Finished. +0ms
  Eleventy
  Eleventy Have a suggestion/feature request/feedback? Feeling frustrated? I want to hear it!
  Eleventy Open an issue: https://github.com/11ty/eleventy/issues/new +0ms

One thing sticks out in the server debug logs:

  Eleventy:Benchmark Benchmark     57ms   0%   573× (Configuration) "@11ty/eleventy-bundle" Transform +0ms
  Eleventy:Benchmark Benchmark    523ms   0%   251× (Configuration) "slugify" Universal Filter +1ms
  Eleventy:Benchmark Benchmark    558ms   0% 12585× (Configuration) "url" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark   3501ms   1%   573× (Configuration) "@11ty/eleventy/html-transformer" Transform +0ms
  Eleventy:Benchmark Benchmark     22ms   0%  1437× (Configuration) "readableDate" Nunjucks Filter +1ms
  Eleventy:Benchmark Benchmark    113ms   0%  1672× (Configuration) "htmlDateString" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      2ms   0%   564× (Configuration) "getCurrentYear" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark     32ms   0%  1129× (Configuration) "jsonMinify" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark     32ms   0%   564× (Configuration) "jsmin" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark     71ms   0%   219× (Configuration) "getWebmentionsForUrl" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      1ms   0%   657× (Configuration) "size" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      2ms   0%   876× (Configuration) "webmentionsByType" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark     69ms   0%   585× (Configuration) "readableDateFromISO" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark     91ms   0%   312× (Configuration) "monthName" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      0ms   0%   312× (Configuration) "getYear" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      2ms   0%   312× (Configuration) "getMonth" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      1ms   0%   203× (Configuration) "getDay" Nunjucks Filter +1ms
  Eleventy:Benchmark Benchmark  18912ms   3%   573× (Configuration) "htmlmin" Transform +0ms
  Eleventy:Benchmark Benchmark      1ms   0%     2× (Configuration) "getNewestCollectionItemDate" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      3ms   0%    13× (Configuration) "dateToRfc3339" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark     65ms   0%   465× (Configuration) "absoluteUrl" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark    186ms   0%    10× (Configuration) "htmlToAbsoluteUrls" Nunjucks Filter +0ms
  Eleventy:Benchmark Benchmark      0ms   0%   223× (Configuration) (count) slugify memoize miss +0ms
  Eleventy:Benchmark Benchmark      0ms   0%    28× (Configuration) (count) slugify memoize hit +0ms
  Eleventy:Benchmark Benchmark     15ms   0%     6× (Aggregate) Configuration addPlugin +70ms
  Eleventy:Benchmark Benchmark      5ms   0%     1× (Aggregate) Processing plugins in config +0ms
  Eleventy:Benchmark Benchmark    143ms   0%     1× (Aggregate) Searching the file system (templates) +0ms
  Eleventy:Benchmark Benchmark  33952ms   6%   374× (Aggregate) Passthrough Copy File +0ms
  Eleventy:Benchmark Benchmark      8ms   0%     1× (Aggregate) Searching the file system (data) +1ms
  Eleventy:Benchmark Benchmark    291ms   0%     1× (Aggregate) Data File +0ms
  Eleventy:Benchmark Benchmark   1474ms   0%   240× (Aggregate) Template Read +0ms
  Eleventy:Benchmark Benchmark      0ms   0%   573× (Aggregate) (count) getOutputLocations +0ms
  Eleventy:Benchmark Benchmark      0ms   0%   465× (Aggregate) (count) Template Compile Cache Miss +1ms
  Eleventy:Benchmark Benchmark     96ms   0%   224× (Aggregate) Template Compile Permalink +0ms
  Eleventy:Benchmark Benchmark    740ms   0%  1158× (Aggregate) Render +0ms
  • Eleventy:Benchmark Benchmark 33952ms 6% 374× (Aggregate) Passthrough Copy File +0ms

Why would passthrough copying take so long?

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

No branches or pull requests

8 participants
@zachleat @nhoizey @tomayac @j9t @Ryuno-Ki @rothsandro @michael-proulx and others