refactor(index): async flow control #405

mweberxyz · 2024-02-13T06:49:53Z

The goal of this commit is to modernize flow control throughout the plugin, converting callback-driven architecture to async-await.

As much as possible, the original flow of the code was kept intact, though a fair amount of error handling was removed, and the errors simply get thrown up to the renderer callers.

Some duplicate logic was factored up, namely all calls to this.header and this.send have been factored up into the reply decorator itself and out of the individual renderers.

Edit: Additional commits factored up minification and page not defined checks out of the individual renderers as well.

Big thanks to @multivoltage for earlier work.

Benchmarks

master on my machine (Node 16 on M1)

% autocannon -c 200 -d 30 -p 20 localhost:3000
Running 30s test @ http://localhost:3000
200 connections with 20 pipelining factor


┌─────────┬───────┬───────┬───────┬───────┬──────────┬──────────┬────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev    │ Max    │
├─────────┼───────┼───────┼───────┼───────┼──────────┼──────────┼────────┤
│ Latency │ 24 ms │ 42 ms │ 73 ms │ 74 ms │ 42.19 ms │ 16.59 ms │ 327 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴──────────┴────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬──────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev    │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼──────────┼─────────┤
│ Req/Sec   │ 71,359  │ 71,359  │ 94,335  │ 95,551  │ 93,657.6 │ 4,173.29 │ 71,310  │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼──────────┼─────────┤
│ Bytes/Sec │ 19.1 MB │ 19.1 MB │ 25.3 MB │ 25.6 MB │ 25.1 MB  │ 1.12 MB  │ 19.1 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴──────────┴─────────┘

and here's the result of this branch:

% autocannon -c 200 -d 30 -p 20 localhost:3000
Running 30s test @ http://localhost:3000
200 connections with 20 pipelining factor


┌─────────┬───────┬───────┬───────┬───────┬──────────┬──────────┬────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev    │ Max    │
├─────────┼───────┼───────┼───────┼───────┼──────────┼──────────┼────────┤
│ Latency │ 24 ms │ 44 ms │ 76 ms │ 78 ms │ 43.06 ms │ 17.99 ms │ 345 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴──────────┴────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬───────────┬──────────┬─────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg       │ Stdev    │ Min     │
├───────────┼────────┼────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Req/Sec   │ 63,231 │ 63,231 │ 92,415  │ 94,271  │ 91,791.47 │ 5,370.73 │ 63,224  │
├───────────┼────────┼────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Bytes/Sec │ 17 MB  │ 17 MB  │ 24.8 MB │ 25.3 MB │ 24.6 MB   │ 1.44 MB  │ 16.9 MB │
└───────────┴────────┴────────┴─────────┴─────────┴───────────┴──────────┴─────────┘

So we potentially have a slight regression at this point, but it seems to be within run-to-run variance. Working further from here, I've managed to get up into the 100k req/s averages with additional refactoring, but wanted to stop here and get this PR up before going any further, so the (hopeful) increase in code maintainability can be weighed versus the slight hit to performance.

Here's an express.js benchmark on my machine just for comparisons sake:

autocannon -c 200 -d 30 -p 20 localhost:3000
Running 30s test @ http://localhost:3000
200 connections with 20 pipelining factor


┌─────────┬───────┬────────┬────────┬────────┬───────────┬───────────┬─────────┐
│ Stat    │ 2.5%  │ 50%    │ 97.5%  │ 99%    │ Avg       │ Stdev     │ Max     │
├─────────┼───────┼────────┼────────┼────────┼───────────┼───────────┼─────────┤
│ Latency │ 88 ms │ 173 ms │ 183 ms │ 192 ms │ 173.97 ms │ 292.88 ms │ 9987 ms │
└─────────┴───────┴────────┴────────┴────────┴───────────┴───────────┴─────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬───────────┬────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg       │ Stdev  │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼────────┼─────────┤
│ Req/Sec   │ 19,007  │ 19,007  │ 22,175  │ 22,415  │ 22,064.54 │ 583.95 │ 19,004  │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼────────┼─────────┤
│ Bytes/Sec │ 6.31 MB │ 6.31 MB │ 7.36 MB │ 7.44 MB │ 7.33 MB   │ 194 kB │ 6.31 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴───────────┴────────┴─────────┘

Checklist

run npm run test
tests and/or benchmarks are included
documentation is changed or added
commit message and code follows the Developer's Certification of Origin
and the Code of conduct

Closes #404

multivoltage · 2024-02-13T08:06:52Z

It's impressive hom much change autocannon -c 200 -d 30 -p 20 localhost:3000 from my MAC (intel 2019) :).
M1 seems to be 4x :)

│ Stat    │ 2.5%   │ 50%    │ 97.5%  │ 99%    │ Avg       │ Stdev    │ Max    │
├─────────┼────────┼────────┼────────┼────────┼───────────┼──────────┼────────┤
│ Latency │ 334 ms │ 350 ms │ 395 ms │ 502 ms │ 354.97 ms │ 30.05 ms │ 730 ms │

I'm curious
What about const readFile = require("node:util").promisify(require("node:fs").readFile);
I tried on your branch and seems to improve perf instead const { readFile } = require('node:fs/promises')

mweberxyz · 2024-02-13T13:31:26Z

@multivoltage This is a MacBook Air (M1, 2020) - and it doesn't even have a cooling fan! The M-series IO is insane.

Regarding the readFile implementation, my initial intuition is that it should not matter in the slightest. In the benchmark, we are running in production-cached mode, so you would expect there to only be a single call to readFile anyways.

Looking further into it is very interesting though - because autocannon hits it with so much load so fast, there are thousands of requests andreadFile calls, before any one request successfully caches the renderer.

Take a look at the results when the benchmark command curl localhost:3000 > /dev/null && autocannon -c 200 -d 5 -p 20 localhost:3000 is used:

require('node:fs/promises') implementation:

┌─────────┬───────┬───────┬───────┬───────┬──────────┬──────────┬─────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev    │ Max     │
├─────────┼───────┼───────┼───────┼───────┼──────────┼──────────┼─────────┤
│ Latency │ 15 ms │ 27 ms │ 58 ms │ 70 ms │ 37.89 ms │ 75.16 ms │ 2181 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴──────────┴─────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬───────────┬──────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg       │ Stdev    │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Req/Sec   │ 95,871  │ 95,871  │ 105,983 │ 106,175 │ 103,980.8 │ 4,071.41 │ 95,827  │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Bytes/Sec │ 25.7 MB │ 25.7 MB │ 28.4 MB │ 28.4 MB │ 27.9 MB   │ 1.09 MB  │ 25.7 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴───────────┴──────────┴─────────┘

const readFile = require("node:util").promisify... implementation

┌─────────┬───────┬───────┬───────┬───────┬───────┬──────────┬─────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg   │ Stdev    │ Max     │
├─────────┼───────┼───────┼───────┼───────┼───────┼──────────┼─────────┤
│ Latency │ 17 ms │ 27 ms │ 60 ms │ 70 ms │ 38 ms │ 62.66 ms │ 1951 ms │
└─────────┴───────┴───────┴───────┴───────┴───────┴──────────┴─────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬───────────┬──────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg       │ Stdev    │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Req/Sec   │ 95,231  │ 95,231  │ 105,791 │ 105,855 │ 103,622.4 │ 4,212.86 │ 95,229  │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Bytes/Sec │ 25.5 MB │ 25.5 MB │ 28.4 MB │ 28.4 MB │ 27.8 MB   │ 1.13 MB  │ 25.5 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴───────────┴──────────┴─────────┘

This gives me the idea of pre-caching the files in templatesDir on load, similar to the way preProcessDot does some work before fastify ready -- will explore after this PR gets some traction.

mweberxyz · 2024-02-14T20:05:36Z

More benchmarks with #407 merged in:

master:

express.js: 24221.34 req/s
fastify.js: 100074.67 req/s
fastify-twig.js: 87040 req/s
fastify-ejs-async.js: 103680 req/s
fastify-ejs-with-layout.js: 91349.34 req/s

refactor/async:

express.js: 24040 req/s
fastify.js: 99754.67 req/s
fastify-twig.js: 89397.34 req/s
fastify-ejs-async.js: 101664 req/s
fastify-ejs-with-layout.js: 83424 req/s

mweberxyz · 2024-02-16T04:05:49Z

Just pushed some light refactoring made possible by the async flow control changes - for some big performance gains!

Benchmarks

Node 16

master:

express.js: 24096 req/s
fastify.js: 97024 req/s
fastify-twig.js: 87061.34 req/s
fastify-ejs-async.js: 104170.67 req/s
fastify-ejs-with-layout.js: 90229.34 req/s

refactor/async as of 050045e:

express.js: 24222.4 req/s
fastify.js: 131557.34 req/s
fastify-twig.js: 109024 req/s
fastify-ejs-async.js: 133402.67 req/s
fastify-ejs-with-layout.js: 116405.34 req/s

That's +35% for the existing benchmark :)

Node 20

master:

express.js: 20168 req/s
fastify.js: 90933.34 req/s
fastify-twig.js: 80192 req/s
fastify-ejs-async.js: 97877.34 req/s
fastify-ejs-with-layout.js: 84138.67 req/s

refactor/async as of 050045e:

express.js: 20210.67 req/s
fastify.js: 113141.34 req/s
fastify-twig.js: 96949.34 req/s
fastify-ejs-async.js: 113120 req/s
fastify-ejs-with-layout.js: 101397.34 req/s

index.js

gurgunday · 2024-02-16T10:01:12Z

This looks pretty good to me!

- viewDecorator: remove spurious defined check - decorateReply: capitalize getHeader check - minify definition: null instead of false when not enabled - getRequestedPath: remove spurious optional chaining - use optional chaining for layout checks - avoid “assign to `x` then return `x`” pattern

mcollina

lgtm

mcollina · 2024-02-17T18:27:17Z

@Uzlopak ptal

mweberxyz · 2024-02-19T02:21:18Z

Pushed a regression test as this refactoring incidentally solves #404

For reference, if the added test is added to master the result of the test run:

Closes fastify#404 Add a regression test for previously incorrect behavior: when the `fastify` instance had an `onError` added, errors thrown by renderer resulted in server crash.

Uzlopak

blocking

Uzlopak · 2024-02-19T15:11:21Z

@mweberxyz

wdyt?

gurgunday · 2024-02-19T15:19:18Z

We need this

mweberxyz · 2024-02-19T15:20:33Z

@Uzlopak lgtm, I will put add the function inside the plugin closure for consistency

index.js

Uzlopak

LGTM

Can we have some new benchmarks, please ;)

mweberxyz · 2024-02-19T16:11:31Z

If we merge #408 we could get high level benchmarks just by adding a tag 😝

Here's the full output (Node v20.11.1, macOS, M1):

master:

% autocannon -c 100 -d 5 -p 10 localhost:3000
Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor


┌─────────┬──────┬───────┬───────┬───────┬──────────┬─────────┬────────┐
│ Stat    │ 2.5% │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max    │
├─────────┼──────┼───────┼───────┼───────┼──────────┼─────────┼────────┤
│ Latency │ 6 ms │ 13 ms │ 14 ms │ 19 ms │ 10.53 ms │ 7.24 ms │ 330 ms │
└─────────┴──────┴───────┴───────┴───────┴──────────┴─────────┴────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬──────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev    │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼──────────┼─────────┤
│ Req/Sec   │ 81,471  │ 81,471  │ 92,543  │ 93,055  │ 90,476.8 │ 4,525.92 │ 81,412  │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼──────────┼─────────┤
│ Bytes/Sec │ 21.8 MB │ 21.8 MB │ 24.8 MB │ 24.9 MB │ 24.2 MB  │ 1.22 MB  │ 21.8 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴──────────┴─────────┘

refactor/async@b13c5dae:

autocannon -c 100 -d 5 -p 10 localhost:3000
Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor


┌─────────┬──────┬───────┬───────┬───────┬─────────┬─────────┬────────┐
│ Stat    │ 2.5% │ 50%   │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max    │
├─────────┼──────┼───────┼───────┼───────┼─────────┼─────────┼────────┤
│ Latency │ 5 ms │ 10 ms │ 11 ms │ 11 ms │ 8.34 ms │ 5.56 ms │ 275 ms │
└─────────┴──────┴───────┴───────┴───────┴─────────┴─────────┴────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬───────────┬──────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg       │ Stdev    │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Req/Sec   │ 103,103 │ 103,103 │ 115,455 │ 115,647 │ 112,979.2 │ 4,954.35 │ 103,080 │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Bytes/Sec │ 27.6 MB │ 27.6 MB │ 30.9 MB │ 31 MB   │ 30.3 MB   │ 1.32 MB  │ 27.6 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴───────────┴──────────┴─────────┘

Uzlopak · 2024-02-19T16:13:16Z

Awesome.

@gurgunday
Merge if you like.

[![Mend Renovate](https://app.renovatebot.com/images/banner.svg)](https://renovatebot.com) This PR contains the following updates: | Package | Change | Age | Adoption | Passing | Confidence | |---|---|---|---|---|---| | [@fastify/view](https://togithub.com/fastify/point-of-view) | [`8.2.0` -> `9.0.0`](https://renovatebot.com/diffs/npm/@fastify%2fview/8.2.0/9.0.0) | [![age](https://developer.mend.io/api/mc/badges/age/npm/@fastify%2fview/9.0.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | [![adoption](https://developer.mend.io/api/mc/badges/adoption/npm/@fastify%2fview/9.0.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | [![passing](https://developer.mend.io/api/mc/badges/compatibility/npm/@fastify%2fview/8.2.0/9.0.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | [![confidence](https://developer.mend.io/api/mc/badges/confidence/npm/@fastify%2fview/8.2.0/9.0.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | --- ### Release Notes <details> <summary>fastify/point-of-view (@fastify/view)</summary> ### [`v9.0.0`](https://togithub.com/fastify/point-of-view/releases/tag/v9.0.0) [Compare Source](https://togithub.com/fastify/point-of-view/compare/v8.2.0...v9.0.0) #### What's Changed - chore(package): explicitly declare js module type by [@Fdawgs](https://togithub.com/Fdawgs) in [fastify/point-of-view#398 - test(eta): replace `typeof` undefined check by [@Fdawgs](https://togithub.com/Fdawgs) in [fastify/point-of-view#400 - build(deps-dev): bump tsd from 0.29.0 to 0.30.0 by [@dependabot](https://togithub.com/dependabot) in [fastify/point-of-view#401 - chore(.gitignore): add .tap/ dir by [@Fdawgs](https://togithub.com/Fdawgs) in [fastify/point-of-view#403 - chore(.prettierignore): add by [@mweberxyz](https://togithub.com/mweberxyz) in [fastify/point-of-view#406 - chore: add benchmarking script, additional benchmarks by [@mweberxyz](https://togithub.com/mweberxyz) in [fastify/point-of-view#407 - build(deps-dev): bump delay from 5.0.0 to 6.0.0 by [@dependabot](https://togithub.com/dependabot) in [fastify/point-of-view#409 - chore(benchmark): remove `delay` dependency by [@mweberxyz](https://togithub.com/mweberxyz) in [fastify/point-of-view#410 - refactor(index): async flow control by [@mweberxyz](https://togithub.com/mweberxyz) in [fastify/point-of-view#405 #### New Contributors - [@mweberxyz](https://togithub.com/mweberxyz) made their first contribution in [fastify/point-of-view#406 **Full Changelog**: fastify/point-of-view@v8.2.0...v9.0.0 </details> --- ### Configuration 📅 **Schedule**: Branch creation - "on sunday" in timezone Asia/Shanghai, Automerge - At any time (no schedule defined). 🚦 **Automerge**: Disabled by config. Please merge this manually once you are satisfied. ♻ **Rebasing**: Whenever PR becomes conflicted, or you tick the rebase/retry checkbox. 🔕 **Ignore**: Close this PR and you won't be reminded about this update again. --- - [ ] If you want to rebase/retry this PR, check this box --- This PR has been generated by [Mend Renovate](https://www.mend.io/free-developer-tools/renovate/). View repository job log [here](https://developer.mend.io/github/PKUHPC/SCOW).  Co-authored-by: renovate[bot] <29139614+renovate[bot]@users.noreply.github.com>

This reverts commit 235f588.

mweberxyz force-pushed the refactor/async branch from 716b5c0 to 8fdce42 Compare February 14, 2024 17:11

refactor(index): async flow control

74d87a0

mweberxyz force-pushed the refactor/async branch from 8fdce42 to 74d87a0 Compare February 16, 2024 00:24

mweberxyz added 3 commits February 15, 2024 20:40

refactor(index): factor up all html minification

fbe2711

refactor(index): remove readCallbackEnd

54329fc

refactor(index): factor up all undefined page checks

050045e