Not properly handling early hints

[Uzlopak]

Running the examples of https://github.com/fastify/fastify-early-hints resulted in some odd behaviour of autocannon and it seems that autocannon has issues to process 103 early hints properly. When sending 10 requests i get 10 x 103 but 0 x 200. With 100 requests I always get 50 x 103 and 50 x 200, so that works. But more than 100 it just gets about 30-40 % x 103 and 60-70% x 200.

When running a 10 second run, I get the totally unrealistic performance of about 1.2 mio req/s. Running without early hints I can get maximum about 600k req/s. So I assume that autocannon counts 103 and 200 twice, despite we have only one response.

uzlopak@Battlestation:~/workspace/fastify-early-hints$ autocannon http://localhost:3000 --renderStatusCodes  -a 10
Running 10 requests test @ http://localhost:3000
10 connections


┌─────────┬──────┬──────┬───────┬──────┬────────┬────────┬──────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg    │ Stdev  │ Max  │
├─────────┼──────┼──────┼───────┼──────┼────────┼────────┼──────┤
│ Latency │ 6 ms │ 7 ms │ 7 ms  │ 7 ms │ 6.8 ms │ 0.4 ms │ 7 ms │
└─────────┴──────┴──────┴───────┴──────┴────────┴────────┴──────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬───────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼───────┼─────────┤
│ Req/Sec   │ 10      │ 10      │ 10      │ 10      │ 10      │ 0     │ 10      │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼───────┼─────────┤
│ Bytes/Sec │ 2.15 kB │ 2.15 kB │ 2.15 kB │ 2.15 kB │ 2.15 kB │ 0 B   │ 2.15 kB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴───────┴─────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 103  │ 10    │
└──────┴───────┘

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

0 2xx responses, 10 non 2xx responses
10 requests in 1.01s, 2.15 kB read

uzlopak@Battlestation:~/workspace/fastify-early-hints$ autocannon http://localhost:3000 --renderStatusCodes  -a 100
Running 100 requests test @ http://localhost:3000
10 connections


┌─────────┬──────┬──────┬───────┬──────┬──────┬─────────┬──────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg  │ Stdev   │ Max  │
├─────────┼──────┼──────┼───────┼──────┼──────┼─────────┼──────┤
│ Latency │ 0 ms │ 0 ms │ 7 ms  │ 8 ms │ 1 ms │ 2.07 ms │ 8 ms │
└─────────┴──────┴──────┴───────┴──────┴──────┴─────────┴──────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬───────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼───────┼─────────┤
│ Req/Sec   │ 100     │ 100     │ 100     │ 100     │ 100     │ 0     │ 100     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼───────┼─────────┤
│ Bytes/Sec │ 13.8 kB │ 13.8 kB │ 13.8 kB │ 13.8 kB │ 13.8 kB │ 0 B   │ 13.8 kB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴───────┴─────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 103  │ 50    │
├──────┼───────┤
│ 200  │ 50    │
└──────┴───────┘

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

50 2xx responses, 50 non 2xx responses
100 requests in 1.01s, 13.8 kB read

uzlopak@Battlestation:~/workspace/fastify-early-hints$ autocannon http://localhost:3000 --renderStatusCodes  -a 1000Running 1000 requests test @ http://localhost:3000
10 connections


┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
│ Latency │ 0 ms │ 0 ms │ 4 ms  │ 7 ms │ 0.31 ms │ 1.12 ms │ 10 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬───────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼───────┼────────┤
│ Req/Sec   │ 1000   │ 1000   │ 1000   │ 1000   │ 1000   │ 0     │ 1000   │
├───────────┼────────┼────────┼────────┼────────┼────────┼───────┼────────┤
│ Bytes/Sec │ 166 kB │ 166 kB │ 166 kB │ 166 kB │ 166 kB │ 0 B   │ 166 kB │
└───────────┴────────┴────────┴────────┴────────┴────────┴───────┴────────┘
┌──────┬───────┐
│ Code │ Count │
├──────┼───────┤
│ 103  │ 325   │
├──────┼───────┤
│ 200  │ 675   │
└──────┴───────┘

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

675 2xx responses, 325 non 2xx responses
1k requests in 1.01s, 166 kB read

uzlopak@Battlestation:~/workspace/fastify-early-hints$ autocannon http://localhost:3000 --renderStatusCodes  
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.08 ms │ 1.25 ms │ 70 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Req/Sec   │ 114879  │ 114879  │ 123263  │ 130239  │ 123046.4 │ 5056.45 │ 114865  │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Bytes/Sec │ 21.6 MB │ 21.6 MB │ 22.8 MB │ 24.4 MB │ 23 MB    │ 940 kB  │ 21.5 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴─────────┴─────────┘
┌──────┬─────────┐
│ Code │ Count   │
├──────┼─────────┤
│ 103  │ 6428    │
├──────┼─────────┤
│ 200  │ 1224046 │
└──────┴─────────┘

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

1224046 2xx responses, 6428 non 2xx responses
1230k requests in 10.01s, 230 MB read

[mcollina]

Thanks for reporting! Would you like to send a Pull Request to address this issue? Remember to add unit tests.