@kurt So I’ve had some time to look into perf again and updated the repo with your type=requests
recommendation to test out perf characteristics with various levels of concurrency: GitHub - lewisl9029/fastify-h2c-test
Live demo to play around with: https://fastify-h2c-test.fly.dev/
When you click run, it’ll fire of a number of simultaneous requests to /noop based on the number in the input box (defaults to 100).
Here’s what I’m seeing in devtools with the default 100 requests:
First handful of requests complete quickly enough, but things get progressively worse for later requests (last few are all in the 160ms ballpark).
Here’s what the last few fastify logs look like:
2022-01-19T05:58:55.228 app[203d7f0a] sjc [info]{"level":30,"time":1642571935228,"pid":536,"hostname":"203d7f0a","reqId":"req-84","res":{"statusCode":200},"responseTime":0.12462399998912588,"msg":"request completed"}
2022-01-19T05:58:55.228 app[203d7f0a] sjc [info]{"level":30,"time":1642571935228,"pid":536,"hostname":"203d7f0a","reqId":"req-85","req":{"method":"GET","url":"/noop?nonce=0.3834155671076118","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45046},"msg":"incoming request"}
2022-01-19T05:58:55.229 app[203d7f0a] sjc [info]{"level":30,"time":1642571935228,"pid":536,"hostname":"203d7f0a","reqId":"req-85","res":{"statusCode":200},"responseTime":0.12235900000086986,"msg":"request completed"}
2022-01-19T05:58:55.229 app[203d7f0a] sjc [info]{"level":30,"time":1642571935228,"pid":536,"hostname":"203d7f0a","reqId":"req-86","req":{"method":"GET","url":"/noop?nonce=0.9519116195985358","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45048},"msg":"incoming request"}
2022-01-19T05:58:55.229 app[203d7f0a] sjc [info]{"level":30,"time":1642571935228,"pid":536,"hostname":"203d7f0a","reqId":"req-86","res":{"statusCode":200},"responseTime":0.1224789999978384,"msg":"request completed"}
2022-01-19T05:58:55.229 app[203d7f0a] sjc [info]{"level":30,"time":1642571935229,"pid":536,"hostname":"203d7f0a","reqId":"req-87","req":{"method":"GET","url":"/noop?nonce=0.9931775853763385","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45082},"msg":"incoming request"}
2022-01-19T05:58:55.229 app[203d7f0a] sjc [info]{"level":30,"time":1642571935229,"pid":536,"hostname":"203d7f0a","reqId":"req-87","res":{"statusCode":200},"responseTime":0.1472759999887785,"msg":"request completed"}
2022-01-19T05:58:55.229 app[203d7f0a] sjc [info]{"level":30,"time":1642571935229,"pid":536,"hostname":"203d7f0a","reqId":"req-88","req":{"method":"GET","url":"/noop?nonce=0.49444808002841656","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45092},"msg":"incoming request"}
2022-01-19T05:58:55.230 app[203d7f0a] sjc [info]{"level":30,"time":1642571935229,"pid":536,"hostname":"203d7f0a","reqId":"req-88","res":{"statusCode":200},"responseTime":0.1578460000018822,"msg":"request completed"}
2022-01-19T05:58:55.230 app[203d7f0a] sjc [info]{"level":30,"time":1642571935229,"pid":536,"hostname":"203d7f0a","reqId":"req-89","req":{"method":"GET","url":"/noop?nonce=0.6833850924027194","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45094},"msg":"incoming request"}
2022-01-19T05:58:55.230 app[203d7f0a] sjc [info]{"level":30,"time":1642571935230,"pid":536,"hostname":"203d7f0a","reqId":"req-89","res":{"statusCode":200},"responseTime":0.6187099999951897,"msg":"request completed"}
2022-01-19T05:58:55.231 app[203d7f0a] sjc [info]{"level":30,"time":1642571935230,"pid":536,"hostname":"203d7f0a","reqId":"req-8a","req":{"method":"GET","url":"/noop?nonce=0.31162930185295434","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45098},"msg":"incoming request"}
2022-01-19T05:58:55.231 app[203d7f0a] sjc [info]{"level":30,"time":1642571935230,"pid":536,"hostname":"203d7f0a","reqId":"req-8a","res":{"statusCode":200},"responseTime":0.14397000000462867,"msg":"request completed"}
2022-01-19T05:58:55.231 app[203d7f0a] sjc [info]{"level":30,"time":1642571935231,"pid":536,"hostname":"203d7f0a","reqId":"req-8b","req":{"method":"GET","url":"/noop?nonce=0.8833881052338448","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45100},"msg":"incoming request"}
2022-01-19T05:58:55.231 app[203d7f0a] sjc [info]{"level":30,"time":1642571935231,"pid":536,"hostname":"203d7f0a","reqId":"req-8b","res":{"statusCode":200},"responseTime":0.14501199999358505,"msg":"request completed"}
2022-01-19T05:58:55.231 app[203d7f0a] sjc [info]{"level":30,"time":1642571935231,"pid":536,"hostname":"203d7f0a","reqId":"req-8c","req":{"method":"GET","url":"/noop?nonce=0.7686686872794564","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45102},"msg":"incoming request"}
2022-01-19T05:58:55.232 app[203d7f0a] sjc [info]{"level":30,"time":1642571935231,"pid":536,"hostname":"203d7f0a","reqId":"req-8c","res":{"statusCode":200},"responseTime":0.14159600000130013,"msg":"request completed"}
2022-01-19T05:58:55.232 app[203d7f0a] sjc [info]{"level":30,"time":1642571935231,"pid":536,"hostname":"203d7f0a","reqId":"req-8d","req":{"method":"GET","url":"/noop?nonce=0.14933176971709217","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45104},"msg":"incoming request"}
2022-01-19T05:58:55.232 app[203d7f0a] sjc [info]{"level":30,"time":1642571935232,"pid":536,"hostname":"203d7f0a","reqId":"req-8d","res":{"statusCode":200},"responseTime":0.1459939999913331,"msg":"request completed"}
2022-01-19T05:58:55.232 app[203d7f0a] sjc [info]{"level":30,"time":1642571935232,"pid":536,"hostname":"203d7f0a","reqId":"req-8e","req":{"method":"GET","url":"/noop?nonce=0.22092260004765896","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45106},"msg":"incoming request"}
2022-01-19T05:58:55.232 app[203d7f0a] sjc [info]{"level":30,"time":1642571935232,"pid":536,"hostname":"203d7f0a","reqId":"req-8e","res":{"statusCode":200},"responseTime":0.13948199999867938,"msg":"request completed"}
2022-01-19T05:58:55.232 app[203d7f0a] sjc [info]{"level":30,"time":1642571935232,"pid":536,"hostname":"203d7f0a","reqId":"req-8f","req":{"method":"GET","url":"/noop?nonce=0.41222002151315107","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45108},"msg":"incoming request"}
2022-01-19T05:58:55.233 app[203d7f0a] sjc [info]{"level":30,"time":1642571935232,"pid":536,"hostname":"203d7f0a","reqId":"req-8f","res":{"statusCode":200},"responseTime":0.14433999999891967,"msg":"request completed"}
2022-01-19T05:58:55.233 app[203d7f0a] sjc [info]{"level":30,"time":1642571935232,"pid":536,"hostname":"203d7f0a","reqId":"req-8g","req":{"method":"GET","url":"/noop?nonce=0.03771367953304372","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45110},"msg":"incoming request"}
2022-01-19T05:58:55.233 app[203d7f0a] sjc [info]{"level":30,"time":1642571935233,"pid":536,"hostname":"203d7f0a","reqId":"req-8g","res":{"statusCode":200},"responseTime":0.13906000000133645,"msg":"request completed"}
2022-01-19T05:58:55.233 app[203d7f0a] sjc [info]{"level":30,"time":1642571935233,"pid":536,"hostname":"203d7f0a","reqId":"req-8h","req":{"method":"GET","url":"/noop?nonce=0.37951247220321815","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45112},"msg":"incoming request"}
2022-01-19T05:58:55.233 app[203d7f0a] sjc [info]{"level":30,"time":1642571935233,"pid":536,"hostname":"203d7f0a","reqId":"req-8h","res":{"statusCode":200},"responseTime":0.14473200000065845,"msg":"request completed"}
2022-01-19T05:58:55.234 app[203d7f0a] sjc [info]{"level":30,"time":1642571935233,"pid":536,"hostname":"203d7f0a","reqId":"req-8i","req":{"method":"GET","url":"/noop?nonce=0.1082447794859942","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45114},"msg":"incoming request"}
2022-01-19T05:58:55.234 app[203d7f0a] sjc [info]{"level":30,"time":1642571935233,"pid":536,"hostname":"203d7f0a","reqId":"req-8i","res":{"statusCode":200},"responseTime":0.14171599999826867,"msg":"request completed"}
2022-01-19T05:58:55.234 app[203d7f0a] sjc [info]{"level":30,"time":1642571935234,"pid":536,"hostname":"203d7f0a","reqId":"req-8j","req":{"method":"GET","url":"/noop?nonce=0.15171719714828713","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45116},"msg":"incoming request"}
2022-01-19T05:58:55.234 app[203d7f0a] sjc [info]{"level":30,"time":1642571935234,"pid":536,"hostname":"203d7f0a","reqId":"req-8j","res":{"statusCode":200},"responseTime":0.14508200000273064,"msg":"request completed"}
2022-01-19T05:58:55.234 app[203d7f0a] sjc [info]{"level":30,"time":1642571935234,"pid":536,"hostname":"203d7f0a","reqId":"req-8k","req":{"method":"GET","url":"/noop?nonce=0.8671808951758786","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45118},"msg":"incoming request"}
2022-01-19T05:58:55.235 app[203d7f0a] sjc [info]{"level":30,"time":1642571935234,"pid":536,"hostname":"203d7f0a","reqId":"req-8k","res":{"statusCode":200},"responseTime":0.14196599999559112,"msg":"request completed"}
2022-01-19T05:58:55.235 app[203d7f0a] sjc [info]{"level":30,"time":1642571935234,"pid":536,"hostname":"203d7f0a","reqId":"req-8l","req":{"method":"GET","url":"/noop?nonce=0.9052876966643939","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45120},"msg":"incoming request"}
2022-01-19T05:58:55.235 app[203d7f0a] sjc [info]{"level":30,"time":1642571935234,"pid":536,"hostname":"203d7f0a","reqId":"req-8l","res":{"statusCode":200},"responseTime":0.14612399999168701,"msg":"request completed"}
2022-01-19T05:58:55.235 app[203d7f0a] sjc [info]{"level":30,"time":1642571935235,"pid":536,"hostname":"203d7f0a","reqId":"req-8m","req":{"method":"GET","url":"/noop?nonce=0.519005828261158","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45122},"msg":"incoming request"}
2022-01-19T05:58:55.235 app[203d7f0a] sjc [info]{"level":30,"time":1642571935235,"pid":536,"hostname":"203d7f0a","reqId":"req-8m","res":{"statusCode":200},"responseTime":0.1408439999941038,"msg":"request completed"}
2022-01-19T05:58:55.235 app[203d7f0a] sjc [info]{"level":30,"time":1642571935235,"pid":536,"hostname":"203d7f0a","reqId":"req-8n","req":{"method":"GET","url":"/noop?nonce=0.9476355703528119","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45124},"msg":"incoming request"}
2022-01-19T05:58:55.236 app[203d7f0a] sjc [info]{"level":30,"time":1642571935235,"pid":536,"hostname":"203d7f0a","reqId":"req-8n","res":{"statusCode":200},"responseTime":0.1441110000014305,"msg":"request completed"}
2022-01-19T05:58:55.236 app[203d7f0a] sjc [info]{"level":30,"time":1642571935235,"pid":536,"hostname":"203d7f0a","reqId":"req-8o","req":{"method":"GET","url":"/noop?nonce=0.5970482323336712","hostname":"fastify-h2c-test.fly.dev","remoteAddress":"::ffff:139.178.89.141","remotePort":45126},"msg":"incoming request"}
2022-01-19T05:58:55.236 app[203d7f0a] sjc [info]{"level":30,"time":1642571935235,"pid":536,"hostname":"203d7f0a","reqId":"req-8o","res":{"statusCode":200},"responseTime":0.14083400000527035,"msg":"request completed"}
All of them complete in less than a millisecond as you’d expect, since the /noop handler only sets a header and returns a hard coded string.
This behavior matches what I’m seeing with my real app at https://app.reflame.dev/ where fly’s proxy seems to add anywhere between 20-100+ ms of latency to the response time logged by fastify when highly concurrent requests are involved.
Any ideas what could be causing this latency and how it can be improved? Could node/fastify be the bottleneck somehow? (maybe it’s lying about the response time in the logs?)