# PHP-FPM unresponsive debugging



## last1 (Nov 30, 2022)

I have a bit of a weird situation with php-fpm. All of a sudden for the past few nights at around 3AM a particular web server that runs apache + php-fpm starts behaving oddly.

The server load goes up to 500/600 and I can't figure out why. Web service stops and in the php-fpm logs I see this:

```
[Wed Nov 30 03:02:50.264359 2022] [proxy:error] [pid 82157:tid 34395073792] (54)Connection reset by peer: AH00957: FCGI: attempt to con
nect to 127.0.0.1:9000 (127.0.0.1:9000) failed
```

In the php-fpm logs I see that it stops logging and the logs just jump in time:

```
[30-Nov-2022 03:02:27] NOTICE: [pool www] child 81068 exited with code 0 after 1118.758260 seconds from start
[30-Nov-2022 03:02:27] NOTICE: [pool www] child 82080 started
[30-Nov-2022 03:13:55] WARNING: [pool www] child 82053 exited on signal 9 (SIGKILL) after 746.754336 seconds from start
[30-Nov-2022 03:13:55] NOTICE: [pool www] child 82226 started
```
/var/log/messages just show connections piling up

```
Nov 30 03:02:50 gomn-2 kernel: sonewconn: pcb 0xfffff8002cf8b7c0 (127.0.0.1:9000 (proto 6)): Listen queue overflow: 193 already in queue awaiting acceptance (1 occurrences)
Nov 30 03:03:50 gomn-2 kernel: sonewconn: pcb 0xfffff8002cf8b7c0 (127.0.0.1:9000 (proto 6)): Listen queue overflow: 193 already in queue awaiting acceptance (454 occurrences)
Nov 30 03:04:50 gomn-2 kernel: sonewconn: pcb 0xfffff8002cf8b7c0 (127.0.0.1:9000 (proto 6)): Listen queue overflow: 193 already in queue awaiting acceptance (426 occurrences)
```
If I manually kill the php-fpm processes things are eventually fine again, but even doing killall -9 php-fpm takes a long time.

I'm on 13.1-RELEASE FreeBSD 13.1-RELEASE and php74-7.4.29

I also tried doing a truss -p on one of the php-fpm processes but it didn't print anything, maybe because of the high load (?)

How can I debug this further ? It will happen again for sure tonight.


----------



## Alain De Vos (Nov 30, 2022)

The outpuf of "netstat -a" can be interesting.


----------



## richardtoohey2 (Nov 30, 2022)

PHP 7.4 is EOL but don't think that 8.x will necessarily fix any issue.

Bump up and check access/error logs to see what the traffic is.

You can also write a cron jon that runs every minute and dumps vital stats from top, netstat, etc. and see if any clues in that.

Any cron jobs at 3 a.m.?

Any changes to the server or what's installed on it?


----------



## last1 (Nov 30, 2022)

I will stay up tonight to see live what's happening.

I ran netstat -m and it seemed fine, but I'll try netstat -a too

There's no cronjobs or other changes.


----------



## last1 (Nov 30, 2022)

richardtoohey2 said:


> PHP 7.4 is EOL but don't think that 8.x will necessarily fix any issue.
> 
> Bump up and check access/error logs to see what the traffic is.
> 
> ...



I do have a new script that I wrote which is supposed to kill hung php-fpm processes but I don't understand why it runs. Basically it connects to php-fpm and gets the status of all threads and kills those that have been running for longer than X seconds. 

so I see this entry in the apache access logs

```
127.0.0.1 - - [30/Nov/2022:03:00:01 -0500] "GET /polstatus?full&json HTTP/1.1" 200 285696
```
but I can't understand why it runs at 03:00 when my cron entry is:

```
*/7     *       *       *       *       /usr/local/bin/perl /usr/local/gtech/kill_hung.pl
```
It should only run at 7,14,21,28,35,42,49,56 , right ?


----------



## SirDice (Nov 30, 2022)

At 3AM periodic(8) usually starts running. What might be happening is that the periodic(8) scripts tend to use a lot of I/O. This may have a detrimental effect on your PHP scripts if they also rely on a lot of I/O. They will start stalling and not handling connections fast enough, which in turn causes the listen queue to overflow. 


```
# Perform daily/weekly/monthly maintenance.
1       3       *       *       *       root    periodic daily
15      4       *       *       6       root    periodic weekly
30      5       1       *       *       root    periodic monthly
```

Try shifting these an hour and see if the timing of your PHP issues also shift along with it. If you have a lot of jails (or VMs) running on the same machine, spread the time around a bit, so they don't ALL start running periodic(8) at the exact same time. 

Also double check the webserver's access and error logs. You may be getting hammered by a bot or some other malware that just happens to hit your site at around the same time.


----------



## richardtoohey2 (Nov 30, 2022)

I've not used php-fpm in production but the times I've had Apache getting swamped the load has built up steadily before the actual meltdown.

So it may not actually be something at 3 a.m. itself - _might_ be a steady build up of traffic in the hours beforehand - that makes it fall over at around 3.

You can also make changes to work around the "Listen queue overflow" sonewconn part e.g. make the queue bigger with this in /etc/sysctl.conf

kern.ipc.soacceptqueue=512

That's just the OS change so you have to tweak web server settings, too.  e.g. ListenBackLog          512 in httpd-mpm.conf (or similar; depends on your web server settings).

But this may just hide an issue you need to fix, so not suggesting you rush in and do this.


----------



## Alain De Vos (Nov 30, 2022)

The security scripts in periodic can do alot of IO.
I disabled them
/etc/periodic.conf

```
daily_queuerun_enable="NO"                # Run mail queue
daily_status_include_submit_mailq="NO"            # Also submit queue
daily_status_security_enable="NO"            # Security check
daily_submit_queuerun="NO"                # Also submit queue
monthly_status_security_enable="NO"            # Security check
security_status_logincheck_enable="NO"
weekly_status_security_enable="NO"            # Security check
```


----------



## last1 (Nov 30, 2022)

SirDice said:


> At 3AM periodic(8) usually starts running. What might be happening is that the periodic(8) scripts tend to use a lot of I/O. This may have a detrimental effect on your PHP scripts if they also rely on a lot of I/O. They will start stalling and not handling connections fast enough, which in turn causes the listen queue to overflow.
> 
> 
> ```
> ...



sweet, I moved them during the day 8,9,10 AM since this box is mostly active at night. Let's see if it changes anything.
Would you also happen to know why a cron entry at */7 runs at 03:00 ?


----------



## Alain De Vos (Nov 30, 2022)

Because at 03:00 most people are asleep. So normally that is the best moment (lowest load)


----------



## covacat (Nov 30, 2022)

*/7 is every 7 minutes for me and probably starting at 0


----------



## richardtoohey2 (Nov 30, 2022)

last1 said:


> I do have a new script that I wrote


And did the issue start/get worse after you used this new script?


----------



## SirDice (Nov 30, 2022)

richardtoohey2 said:


> So it may not actually be something at 3 a.m. itself - _might_ be a steady build up of traffic in the hours beforehand - that makes it fall over at around 3.


It's certainly possible it was already limping along and the 3am periodic(8) pushes it over the edge.


----------



## last1 (Dec 1, 2022)

covacat said:


> */7 is every 7 minutes for me and probably starting at 0



ah ok, I didn't get that from the man page, I thought it would run every 7 minutes starting with the first number divisible by 7, but yeah 0/7 works too


----------



## last1 (Dec 2, 2022)

Moving the periodic run to 8AM when the box is much less used appears to have solved the problem.

Thank you all for your help!


----------

