nodes_perf_compare

Simple RPS comparison between some nodejs frameworks (express, fastify, etc...) with / without logging to console.log with / without piping stdout to other process

TL;DR

Logs has hugh impact on performance event with simple logging. Fastify without logs is much faster than express (100% faster)

Fastify without logs - 315K/10s

Express without logs - 169k/10s

Difference between writing and not writing logs can be of one order magnitude difference (30k->315K requests per 10 seconds)

Piping the stdout stream to another process can speed up the program by 100% (from 30K to 66K requests per 10 seconds)

Reproduce Results Yourself

To run the tests:

1. npm i -g autocannon - a utility to create a load against the server
2. start one of the servers, i.e. node express.js / node fastify-no-logs.js
3. in another terminal run autocannon http://localhost:3000
4. results would be printed on screen

Results

express server

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

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
│ Latency │ 0 ms │ 0 ms │ 1 ms  │ 1 ms │ 0.15 ms │ 0.41 ms │ 18 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 8919    │ 8919    │ 16415   │ 16815   │ 15364   │ 2221.62 │ 8912    │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 2.04 MB │ 2.04 MB │ 3.76 MB │ 3.85 MB │ 3.52 MB │ 509 kB  │ 2.04 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

169k requests in 11.04s, 38.7 MB read

express with logs

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

┌─────────┬──────┬──────┬───────┬───────┬────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg    │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼───────┼────────┼─────────┼──────────┤
│ Latency │ 0 ms │ 1 ms │ 9 ms  │ 11 ms │ 2.7 ms │ 2.67 ms │ 27.58 ms │
└─────────┴──────┴──────┴───────┴───────┴────────┴─────────┴──────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev  │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼────────┼────────┤
│ Req/Sec   │ 1527   │ 1527   │ 3207   │ 4243   │ 3124.4 │ 854.86 │ 1527   │
├───────────┼────────┼────────┼────────┼────────┼────────┼────────┼────────┤
│ Bytes/Sec │ 350 kB │ 350 kB │ 735 kB │ 971 kB │ 715 kB │ 196 kB │ 350 kB │
└───────────┴────────┴────────┴────────┴────────┴────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

31k requests in 10.03s, 7.15 MB read

express with logs, stdout piped to grep (node express-with-logs.js | grep GET)

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

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬─────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max     │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼─────────┤
│ Latency │ 0 ms │ 1 ms │ 4 ms  │ 5 ms │ 0.99 ms │ 1.08 ms │ 21.5 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴─────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬─────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min    │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼─────────┼────────┤
│ Req/Sec   │ 2225   │ 2225   │ 7235    │ 8123    │ 6616.4  │ 1870.77 │ 2224   │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼─────────┼────────┤
│ Bytes/Sec │ 509 kB │ 509 kB │ 1.66 MB │ 1.86 MB │ 1.52 MB │ 428 kB  │ 509 kB │
└───────────┴────────┴────────┴─────────┴─────────┴─────────┴─────────┴────────┘

Req/Bytes counts sampled once per second.

66k requests in 10.04s, 15.2 MB read

fastify-with-logs

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

┌─────────┬──────┬──────┬───────┬───────┬────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg    │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼───────┼────────┼─────────┼──────────┤
│ Latency │ 0 ms │ 2 ms │ 15 ms │ 18 ms │ 4.2 ms │ 4.81 ms │ 49.24 ms │
└─────────┴──────┴──────┴───────┴───────┴────────┴─────────┴──────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev  │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼────────┼────────┤
│ Req/Sec   │ 1190   │ 1190   │ 1766   │ 3097   │ 2117.9 │ 716.16 │ 1190   │
├───────────┼────────┼────────┼────────┼────────┼────────┼────────┼────────┤
│ Bytes/Sec │ 195 kB │ 195 kB │ 290 kB │ 508 kB │ 347 kB │ 117 kB │ 195 kB │
└───────────┴────────┴────────┴────────┴────────┴────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

21k requests in 10.03s, 3.47 MB read

fastify-with-logs piped to grep reqId

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

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max       │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────────┤
│ Latency │ 0 ms │ 0 ms │ 3 ms  │ 8 ms │ 0.66 ms │ 8.95 ms │ 643.48 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬─────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min    │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼─────────┼────────┤
│ Req/Sec   │ 2377   │ 2377   │ 7011    │ 15119   │ 8522.21 │ 4155.75 │ 2377   │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼─────────┼────────┤
│ Bytes/Sec │ 390 kB │ 390 kB │ 1.15 MB │ 2.48 MB │ 1.4 MB  │ 682 kB  │ 390 kB │
└───────────┴────────┴────────┴─────────┴─────────┴─────────┴─────────┴────────┘

Req/Bytes counts sampled once per second.

85k requests in 10.06s, 14 MB read

fastify no logs

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

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼──────────┤
│ Latency │ 0 ms │ 0 ms │ 0 ms  │ 0 ms │ 0.01 ms │ 0.13 ms │ 16.89 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴──────────┘
┌───────────┬─────────┬─────────┬────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%    │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 23343   │ 23343   │ 32351  │ 32655   │ 31496   │ 2732.86 │ 23333   │
├───────────┼─────────┼─────────┼────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 3.83 MB │ 3.83 MB │ 5.3 MB │ 5.35 MB │ 5.16 MB │ 448 kB  │ 3.83 MB │
└───────────┴─────────┴─────────┴────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

315k requests in 10.04s, 51.6 MB read