Cached routes significantly decrease throughput

[InstantlyMoist]

Environment

Node v22.2.0
Nitro latest (as of posting)

Reproduction

https://github.com/InstantlyMoist/nitro-throughput

Describe the bug

Currently it appears that using a cached event handler reduces the throughput of a route by around 40% this is tested with

https://github.com/fomalhaut88/winrk but can also be tested with wrk for linux.

My findings (based on reproduction)
For all endpoints I used the same settings (t = 4, d = 10, c = 200), tested 3 times

/simple = ~16k requests per second
/simple_cached = ~11k requests per second
/big_payload = ~100 requests per second
/big_payload_cached = ~60 request per second

While nitro's throughput seems to significantly decrease with a higher payload, it seems to decrease even further with the use of a cached event route.

Additional context

No response

Logs

No response

[TheAlexLichter]

(Linking Discord discussion here)

[pi0]

Hi dear @InstantlyMoist. You should use caching when the computation cost is more than cache retrieval like when making a costly database query or long-time fetch.

In the /simple example, computing a simple new Date() is actually cheaper than more instructions needed to store and retrieve the cache.

In the /big_payload case, we are actually not computing anything. Returning a JS object is also significantly cheaper than serializing it to store it in the cache and deserializing it before sending a response.

We can improve Nitro DX though to show some info in about it ~> #2559

[TheAlexLichter]

As an addition to the difference in time. This is because of the gigantic JSON. As comparison, express does even worse on my machine compared to what I get for the payload on Nitro

You should definitely paginate your content and not bring out all of them at once. Or you might want to serve the content fully static, or use a different caching option than in-memory.

[cjpearson]

I've also been testing out the performance of Nitro's cachedEventHandler. I noticed that as the payload grows, a larger percentage of the execution time is taken up by serializing and deserializing the JSON.

When profiling /big_payload_cached I see destr taking up a bit over 50% of the time (compared to ~2% for /simple_cached). This JSON is admittedly gigantic, but it's also noticeable in more realistic scenarios. For returning cached pages in our Nuxt application, about a third of the time is spent by destr.

One idea is to use getItemRaw/setItemRaw to avoid serialization. I made a quick test patch to save the cached payload in the raw format and save the metadata in JSON. With these changes, the performance of /big_payload and /big_payload_cached is comparable.

Before Patch

Running 10s test @ http://localhost:3000/big_payload
10 connections


┌─────────┬───────┬───────┬────────┬────────┬──────────┬──────────┬────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5%  │ 99%    │ Avg      │ Stdev    │ Max    │
├─────────┼───────┼───────┼────────┼────────┼──────────┼──────────┼────────┤
│ Latency │ 46 ms │ 49 ms │ 101 ms │ 105 ms │ 54.67 ms │ 16.73 ms │ 145 ms │
└─────────┴───────┴───────┴────────┴────────┴──────────┴──────────┴────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬───────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼───────┼────────┤
│ Req/Sec   │ 169    │ 169    │ 181    │ 186    │ 180.7  │ 4.95  │ 169    │
├───────────┼────────┼────────┼────────┼────────┼────────┼───────┼────────┤
│ Bytes/Sec │ 481 MB │ 481 MB │ 515 MB │ 530 MB │ 514 MB │ 14 MB │ 481 MB │
└───────────┴────────┴────────┴────────┴────────┴────────┴───────┴────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 200  │ 1807  │
└──────┴───────┘

Req/Bytes counts sampled once per second.
# of samples: 10

2k requests in 10.01s, 5.14 GB read

Running 10s test @ http://localhost:3000/big_payload_cached
10 connections


┌─────────┬───────┬────────┬────────┬────────┬───────────┬──────────┬────────┐
│ Stat    │ 2.5%  │ 50%    │ 97.5%  │ 99%    │ Avg       │ Stdev    │ Max    │
├─────────┼───────┼────────┼────────┼────────┼───────────┼──────────┼────────┤
│ Latency │ 98 ms │ 103 ms │ 209 ms │ 231 ms │ 115.42 ms │ 35.87 ms │ 265 ms │
└─────────┴───────┴────────┴────────┴────────┴───────────┴──────────┴────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev   │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Req/Sec   │ 74     │ 74     │ 86     │ 90     │ 85.8   │ 4.45    │ 74     │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Bytes/Sec │ 211 MB │ 211 MB │ 245 MB │ 256 MB │ 244 MB │ 12.6 MB │ 211 MB │
└───────────┴────────┴────────┴────────┴────────┴────────┴─────────┴────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 200  │ 858   │
└──────┴───────┘

Req/Bytes counts sampled once per second.
# of samples: 10

868 requests in 10.04s, 2.44 GB read

After Patch

Running 10s test @ http://localhost:3000/big_payload
10 connections


┌─────────┬───────┬───────┬───────┬────────┬──────────┬──────────┬────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%    │ Avg      │ Stdev    │ Max    │
├─────────┼───────┼───────┼───────┼────────┼──────────┼──────────┼────────┤
│ Latency │ 44 ms │ 48 ms │ 98 ms │ 104 ms │ 53.75 ms │ 15.88 ms │ 116 ms │
└─────────┴───────┴───────┴───────┴────────┴──────────┴──────────┴────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev   │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Req/Sec   │ 177    │ 177    │ 183    │ 189    │ 184    │ 3.77    │ 177    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Bytes/Sec │ 504 MB │ 504 MB │ 521 MB │ 538 MB │ 524 MB │ 10.7 MB │ 504 MB │
└───────────┴────────┴────────┴────────┴────────┴────────┴─────────┴────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 200  │ 1840  │
└──────┴───────┘

Req/Bytes counts sampled once per second.
# of samples: 10

2k requests in 10.02s, 5.24 GB read

Running 10s test @ http://localhost:3000/big_payload_cached
10 connections


┌─────────┬───────┬───────┬────────┬────────┬─────────┬──────────┬────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5%  │ 99%    │ Avg     │ Stdev    │ Max    │
├─────────┼───────┼───────┼────────┼────────┼─────────┼──────────┼────────┤
│ Latency │ 45 ms │ 48 ms │ 100 ms │ 105 ms │ 54.1 ms │ 16.04 ms │ 120 ms │
└─────────┴───────┴───────┴────────┴────────┴─────────┴──────────┴────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev   │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Req/Sec   │ 172    │ 172    │ 183    │ 188    │ 182.6  │ 4.32    │ 172    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Bytes/Sec │ 490 MB │ 490 MB │ 521 MB │ 535 MB │ 520 MB │ 12.3 MB │ 490 MB │
└───────────┴────────┴────────┴────────┴────────┴────────┴─────────┴────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 200  │ 1826  │
└──────┴───────┘

Req/Bytes counts sampled once per second.
# of samples: 10

2k requests in 10.01s, 5.2 GB read

Would an approach like this make sense?

[cjpearson]

I did some more exploration around this topic and did some testing with oha.

Before

big_payload

Summary:
Success rate: 100.00%
Total: 30.0015 secs
Slowest: 0.1975 secs
Fastest: 0.0118 secs
Average: 0.0589 secs
Requests/sec: 170.0582

Total data: 13.50 GiB
Size/request: 2.71 MiB
Size/sec: 460.77 MiB

big_payload_cached

Summary:
Success rate: 100.00%
Total: 30.0024 secs
Slowest: 0.2994 secs
Fastest: 0.0162 secs
Average: 0.1226 secs
Requests/sec: 81.7267

Total data: 6.47 GiB
Size/request: 2.71 MiB
Size/sec: 220.97 MiB

simple

Summary:
Success rate: 100.00%
Total: 30.0010 secs
Slowest: 0.0122 secs
Fastest: 0.0000 secs
Average: 0.0002 secs
Requests/sec: 41232.3910

Total data: 15.34 MiB
Size/request: 13 B
Size/sec: 523.45 KiB

simple_cached

Summary:
Success rate: 100.00%
Total: 30.0009 secs
Slowest: 0.0253 secs
Fastest: 0.0000 secs
Average: 0.0003 secs
Requests/sec: 28722.9653

Total data: 10.68 MiB
Size/request: 13 B
Size/sec: 364.65 KiB

After

big_payload

Summary:
Success rate: 100.00%
Total: 30.0023 secs
Slowest: 0.1576 secs
Fastest: 0.0148 secs
Average: 0.0584 secs
Requests/sec: 171.4868

Total data: 13.61 GiB
Size/request: 2.71 MiB
Size/sec: 464.65 MiB

big_payload_cached

Summary:
Success rate: 100.00%
Total: 30.0029 secs
Slowest: 0.2506 secs
Fastest: 0.0135 secs
Average: 0.0583 secs
Requests/sec: 171.5500

Total data: 13.62 GiB
Size/request: 2.71 MiB
Size/sec: 464.82 MiB

simple

Summary:
Success rate: 100.00%
Total: 30.0011 secs
Slowest: 0.1038 secs
Fastest: 0.0000 secs
Average: 0.0002 secs
Requests/sec: 39992.4689

Total data: 14.87 MiB
Size/request: 13 B
Size/sec: 507.71 KiB

simple_cached

Summary:
Success rate: 100.00%
Total: 30.0004 secs
Slowest: 0.0122 secs
Fastest: 0.0000 secs
Average: 0.0003 secs
Requests/sec: 29586.3400

Total data: 11.00 MiB
Size/request: 13 B
Size/sec: 375.60 KiB

The changes can be seen here.

[cjpearson]

@pi0 with nitro v3 on the horizon, I wanted to bump this topic and get your thoughts on this approach. Doing some load tests on our application showed about a 25x improvement in average latency and throughput for the SSR cache.

Since it changes the cache format it would be a breaking change, unless it's made optional. If it's something you might consider, I could rebase the changes to the v3 branch.