Level 61
Return those numbers to default and you should see the improvement. Give more info on servers in order to get more detailed answer.
Dec 1, 2020
21
Level 2
executing too slow & execution timed out
Hi everyone,
We have a setup as follows:
- Do load balancer
- Do managed DB Redis for cache, session etc
- Do managed DB MySql
- Forge provisioned app server with php-fpm pool set to:
pm = dynamic pm.max_children = 400 pm.start_servers = 120 pm.min_spare_servers = 120 pm.max_spare_servers = 280 pm.max_requests = 1000 request_terminate_timeout = 0
nginx config also has:
fastcgi_keep_conn off;
But for some reason our logs get filled with: (request: "GET /index.php") executing too slow (10.325925 sec), logging (request: "GET /index.php") execution timed out (13.660117 sec), terminating
even with a simple view just loading a logo and nothing else.
Would anyone have any ideas on how we could solve this issue?
Thanks in advance for your time in responding.
Level 73
Have you checked that all the cloud servers are in the same area so you don't have one in US one in EU and one in Asia?
Level 2
Thanks for the quick replies!
The app servers are 8GB / 4 cpu so should have more then enough capacity and are all located in the same datacenter of DO in FRA1.
I have been playing around with the default values as well, but it keeps on giving the same issues really.
Level 61
That is not enough RAM for pm.max_children configuration that you've specified. You should check how much memory on average php-fpm is using in terminal with ps command and based on that calculate how much to put.
Usually php-fpm is using between 40-80MB. So in your case, you should also leave some breathing room for the system, that should be far less.
$ram = 8 * 1024;
$forSystem = 1024;
$averagePhpFpmMemoryUsage = 80; // I would even bump this for at least 5MB up so it is 85
echo ($ram - $forSystem) / $averagePhpFpmMemoryUsage; // ~90
Level 2
Thanks for this! Well give this a shot and see what it does. Until now we have used the calculator that can be found here: https://spot13.com/pmcalculator/
Ill post back here with the results.
Level 61
That calculator looks OK, but you've probably defined wrong input. I have some apps where php-fpm average is around 100MB.
Level 61
There is even an article written by the creator of that calculator saying that it is using 100MB per php-fpm process https://chrismoore.ca/2018/10/finding-the-correct-pm-max-children-settings-for-php-fpm/
Level 2
Yeah we might have grabbed the wrong value from debugbar for this I recon now! Im updating this now with conservative numbers to see what happens, but for now im still seeing the same error, even when I turned it down to pm.max_children = 40
Level 2
Yeah, still seeing the same issue with 502 Bad gateway message now
Level 61
Yeah we might have grabbed the wrong value from debugbar for this I recon now!
That is not correct info that you need for this use.
Yeah, still seeing the same issue with 502 Bad gateway message now
Have you tried restarting servers? Also what do the logs say? Is it a code error or setup error?
Level 61
Also have you changed it on all servers?
Level 2
Thanks @bugsysha, lesson learned on where to grab that value from.
I did restart the servers and changed it on both, the error now changed from 504 to 502 tough.
Level 61
HTTP status code does not give enough info. Post here contents from the log files.
Level 2
Hi @bugsysha,
I have been monitoring the situation after tweaking everything overnight after your advice. It seems things have calmed down a bit, but still getting a lot of these in the fpm log:
[02-Dec-2020 10:21:38] WARNING: [pool www] child 16986, script '/home/forge/--/public/index.php' (request: "GET /index.php") executing too slow (10.512399 sec), logging [02-Dec-2020 10:21:38] NOTICE: child 16986 stopped for tracing [02-Dec-2020 10:21:38] NOTICE: about to trace 16986 [02-Dec-2020 10:21:38] NOTICE: finished trace of 16986 [02-Dec-2020 10:22:28] WARNING: [pool www] child 16986, script '/home/forge/--/public/index.php' (request: "GET /index.php") execution timed out (60.529634 sec), terminating [02-Dec-2020 10:22:28] WARNING: [pool www] child 16986 exited on signal 15 (SIGTERM) after 2553.946430 seconds from start
And then in slowlog I can find lines like these:
[02-Dec-2020 07:49:35] [pool www] pid 11872 script_filename = /home/forge/--/public/index.php [0x00007f334ae141e0] auth() /home/forge/--/vendor/laravel/framework/src/Illuminate/Redis/Connectors/PhpRedisConnector.php:87 [0x00007f334ae14150] Illuminate\Redis\Connectors{closure}() /home/forge/--/vendor/laravel/framework/src/Illuminate/Support/helpers.php:433 [0x00007f334ae140d0] tap() /home/forge/--/vendor/laravel/framework/src/Illuminate/Redis/Connectors/PhpRedisConnector.php:105 [0x00007f334ae14060] createClient() /home/forge/--/vendor/laravel/framework/src/Illuminate/Redis/Connectors/PhpRedisConnector.php:28 [0x00007f334ae13fe0] Illuminate\Redis\Connectors{closure}() /home/forge/--/vendor/laravel/framework/src/Illuminate/Redis/Connectors/PhpRedisConnector.php:32 [0x00007f334ae13ec0] connect() /home/forge/--/vendor/laravel/framework/src/Illuminate/Redis/RedisManager.php:110 [0x00007f334ae13e10] resolve() /home/forge/--/vendor/laravel/framework/src/Illuminate/Redis/RedisManager.php:90 [0x00007f334ae13d00] connection() /home/forge/--/vendor/laravel/framework/src/Illuminate/Cache/RedisStore.php:242 [0x00007f334ae13ca0] connection() /home/forge/--/vendor/laravel/framework/src/Illuminate/Cache/RedisStore.php:54 [0x00007f334ae13c10] get() /home/forge/--/vendor/laravel/framework/src/Illuminate/Cache/Repository.php:97 [0x00007f334ae13b80] get() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/CacheBasedSessionHandler.php:58 [0x00007f334ae13b10] read() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Store.php:97 [0x00007f334ae13a90] readFromHandler() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Store.php:87 [0x00007f334ae139c0] loadSession() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Store.php:71 [0x00007f334ae13960] start() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Middleware/StartSession.php:142 [0x00007f334ae138f0] Illuminate\Session\Middleware{closure}() /home/forge/--/vendor/laravel/framework/src/Illuminate/Support/helpers.php:433 [0x00007f334ae13870] tap() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Middleware/StartSession.php:143 [0x00007f334ae137f0] startSession() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Middleware/StartSession.php:111 [0x00007f334ae136f0] handleStatefulRequest() /home/forge/--/vendor/laravel/framework/src/Illuminate/Session/Middleware/StartSession.php:62 [0x00007f334ae13640] handle() /home/forge/--/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php:167
Thanks once again!
Level 61
Are you sure you've configured everything correctly like using local IP addresses instead of public ones?
Level 2
Yeah, it's all using private network connections within DO.
We use DO Load balancer, then three droplets as web servers, and behind those we connect over private network to managed Redis cluster and managed MySQL cluster... all in the FRA1 region.
Level 61
If everything is configured correctly or with default values then I would try following in specified order:
- deploy clean Laravel app to see if everything works
- try clean Laravel app on Hetzner with same stack and see how it is behaving, also with your app
Level 10
@markvdp Hey mark. I have a similar setup with a digitalocean droplet, a managed database and a managed redis. I get the same slow logs like you and some php processes are timed out , too. Did you solve your problem?
Do you think it could be something with redis?
Kind regards Chris
Level 10
Reading from the slow log:
auth() /home/forge/app-name/releases/20210525143804/vendor/laravel/framework/src/Illuminate/Redis/Connectors/PhpRedisConnector.php:87
There is always the auth() method , when the timeout happens, so my guess is , that there is something stuck with the redis authentication maybe?
Level 2
Hi @chrissfr,
I could not figure it out, even hired some external people, could not figure it out, so only option I found was to move our Redis away from Digital Ocean to Redislabs.
Digital Ocean support is super unhelpful when it comes to these things, and im not happy with their support at all, we have quite a big account there and even then the answers are really short and never really helpful at all as its always something else.
So for the stability of our platforms I decided to move over to Redislabs and have not had a single issue since then and thus would really recommend them.
- Mark
Level 10
Hi @markvdp , thanks for your response. Investigated a lot in this issue and just saw this issue here: https://github.com/phpredis/phpredis/issues/1726
There are multiple people, who have similar random Redis auth() connection freezes, which are leading to PHP timeouts.
It seems that it's not directly an phpredis issue. It's more an issue of the new tls 1.3 protocol.
Someone reported that using tlsv1.2:// instead of the 1.3 default is solving this issue for him. But it's not really satisfying for me. Sadly the issue was closed, because it's not php related.
I find it stupid that there is no connection abort or an error is thrown in the logs.
Btw I'm wondering why it's working for you with Redislabs. Do you connect via another protocol?
Please or to participate in this conversation.