search

roadrunner-server / roadrunner

🤯 High-performance PHP application server, process manager written in Go and powered with plugins
https://docs.roadrunner.dev
MIT License
7.91k stars 414 forks source link

Concurrent request problem in Laravel Octane #1823

Closed foremtehan closed 10 months ago

foremtehan commented 10 months ago

What happened?

Had a chance to get hands-on experience with RR with fresh laravel octane app.

It was working great until an I/O was involved in the app or the app faced high load.

image

I just added a network request that sleeps for a second

php artisan octane:start --host=0.0.0.0 --workers=15 --task-workers=15

and here's the benchmarker:

ab -n 500 -c10  ip:port

https://github.com/roadrunner-server/roadrunner/assets/53290883/5b00419b-fbc2-460f-a495-4ba874e5fe99

As you can see in the above video, RR can only handle 3 or 4 requests at the same time (the first two second seems good but after that it slows down), The number of workers and task workers is set to 15.

How can I increase the threads or whatever improves concurrent request handling?

Also if you see the response time it's not 1000ms and looks increasing why ?

rustatian commented 10 months ago

Hey @foremtehan 👋 Could you please add sleep 15s to the Octane-RR worker, use the same number of workers (15) and refresh the starting page 15 times. And, before that sleep, add some log, e.g. before sleep. You should see 15 log entries with the before sleep. Just to be sure 😃

foremtehan commented 10 months ago

The http server handle with octane itself, these are the options before we start the server:

image

Which one?

rustatian commented 10 months ago

BTW, according to your benchmark, you used ab -c 10. Which means, that ab will send 10 concurrent requests at the time. If you wait for a second and count the number of 200 GET /... Octane debug logs, you'll see exactly 10 responses arrived at the same time.

foremtehan commented 10 months ago

Ok let me add logger

foremtehan commented 10 months ago 
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:11] local.DEBUG: 1703620031
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:14] local.DEBUG: 1703620034
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:16] local.DEBUG: 1703620036
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:18] local.DEBUG: 1703620038
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:20] local.DEBUG: 1703620040
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:22] local.DEBUG: 1703620042
[2023-12-26 19:47:24] local.DEBUG: 1703620044
[2023-12-26 19:47:24] local.DEBUG: 1703620044
[2023-12-26 19:47:24] local.DEBUG: 1703620044
[2023-12-26 19:47:24] local.DEBUG: 1703620044
[2023-12-26 19:47:24] local.DEBUG: 1703620044
[2023-12-26 19:47:24] local.DEBUG: 1703620044
[2023-12-26 19:47:25] local.DEBUG: 1703620045
[2023-12-26 19:47:25] local.DEBUG: 1703620045
[2023-12-26 19:47:25] local.DEBUG: 1703620045
[2023-12-26 19:47:25] local.DEBUG: 1703620045
[2023-12-26 19:47:26] local.DEBUG: 1703620046
[2023-12-26 19:47:26] local.DEBUG: 1703620046
[2023-12-26 19:47:26] local.DEBUG: 1703620046
[2023-12-26 19:47:26] local.DEBUG: 1703620046
[2023-12-26 19:47:26] local.DEBUG: 1703620046
[2023-12-26 19:47:26] local.DEBUG: 1703620046
[2023-12-26 19:47:27] local.DEBUG: 1703620047
[2023-12-26 19:47:27] local.DEBUG: 1703620047
[2023-12-26 19:47:27] local.DEBUG: 1703620047
[2023-12-26 19:47:27] local.DEBUG: 1703620047
[2023-12-26 19:47:28] local.DEBUG: 1703620048
[2023-12-26 19:47:28] local.DEBUG: 1703620048
[2023-12-26 19:47:28] local.DEBUG: 1703620048
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:29] local.DEBUG: 1703620049
[2023-12-26 19:47:30] local.DEBUG: 1703620050
[2023-12-26 19:47:30] local.DEBUG: 1703620050
[2023-12-26 19:47:30] local.DEBUG: 1703620050
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:31] local.DEBUG: 1703620051
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:33] local.DEBUG: 1703620053
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:35] local.DEBUG: 1703620055
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:37] local.DEBUG: 1703620057
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059
[2023-12-26 19:47:39] local.DEBUG: 1703620059

looks it handles 3 up to 15 concurrent request,

Also the response time is increasing (saw 2000ms) in the terminal

rustatian commented 10 months ago

You have ab -c 10, 10 requests at the time. According to your log, you have 10 responses at the time:

[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
[2023-12-26 19:47:09] local.DEBUG: 1703620029
rustatian commented 10 months ago

2000ms is quite a long response. But, all credits go to the Octane 😃 RR just passes the request to the worker, which takes 100-200 microseconds internally. BTW, Octane doesn't support Queues (Kafka, RabbitMQ, etc), Temporal (https://temporal.io), KV, gRPC, websockets bidirectional transport (Centrifuge) and other cool RR features.