Edit report at https://bugs.php.net/bug.php?id=61558&edit=1
ID: 61558
Comment by: Danack at basereality dot com
Reported by: phpbug2012 at tgabber dot mine dot nu
Summary: Runaway spawning of children after pipe error
Status: Assigned
Type: Bug
Package: FPM related
Operating System: Debian Linux
PHP Version: 5.3.10
Assigned To: tony2001
Block user comment: N
Private report: N
New Comment:
I think there is an easier way to trigger this (and probably something that I'll open as a
separate bug):
i) Include a library function in an extension.
ii) Don't include the library in the linking step for php-fpm.
iii) Watch the error log fill up with:
[24-Jul-2014 18:58:27] NOTICE: [pool www] child 22710 started
[24-Jul-2014 18:58:27] WARNING: [pool www] child 22710 exited with code 127 after 0.044963 seconds
from start
[24-Jul-2014 18:58:27] WARNING: [pool www] child 22710 said into stderr: "php-fpm: pool www:
symbol lookup error: /usr/local/lib/php/extensions/no-debug-zts-20131226/imagick.so: undefined
symbol: GetMagickVersion"
Once this happens you need to kill -9 the php-fpm master process to stop it spawning pool workers.
Obviously there shouldn't be errors like this in an extension, but also PHP-FPM shouldn't
become unresponsive and start spawning workers like crazy.
Previous Comments:
------------------------------------------------------------------------
[2013-05-23 13:44:24] pavel at stack dot ee
PHP 5.3.23 with Suhosin-Patch (cli) (built: Mar 26 2013 14:07:09)
Copyright (c) 1997-2013 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2013 Zend Technologies
FPM POOL CONFIG:
[storage]
listen = /tmp/fpm_storage.sock
listen.owner = storage
listen.group = storage
listen.mode = 0666
user = storage
group = storage
pm = dynamic
pm.max_children = 50
pm.start_servers = 10
pm.min_spare_servers = 5
pm.max_spare_servers = 35
NGINX:
location ~ \.php$ {
fastcgi_pass unix:/tmp/fpm_storage.sock;
fastcgi_index index.php;
include fastcgi_params;
fastcgi_param DEVENV on;
fastcgi_intercept_errors on;
fastcgi_ignore_client_abort off;
fastcgi_connect_timeout 60;
fastcgi_send_timeout 180;
fastcgi_read_timeout 180;
fastcgi_buffer_size 128k;
fastcgi_buffers 4 256k;
fastcgi_busy_buffers_size 256k;
fastcgi_temp_file_write_size 256k;
}
~/.ssh/config:
Host *
ConnectTimeout 2
TCPKeepAlive yes
Port 22
Identityfile ~/.ssh/server1000
ControlMaster no
ControlPath ~/.ssh/master-%r@%h:%p
Host server1000
Hostname 192.168.2.2
Creating connection to remote server:
# ssh -o "ServerAliveInterval 15" -o "ServerAliveCountMax 1" -MN user@server1000
# ls -la ~/.ssh/
srw------- 1 storage storage 0 Mar 26 15:46 master-root@192.168.2.2:22
# ssh server1000 whoami
root
and this simple script for which was run from browser and i'm getting same behaviour in Debian
and FreeBSD
<?php
for ($i = 0; $i < 100; ++$i) {
echo exec("ssh root@192.168.2.2 ls -la");
}
?>
[26-Mar-2013 15:57:00] NOTICE: configuration file /etc/php5/fpm/php-fpm.conf test is successful
[26-Mar-2013 15:57:00] NOTICE: fpm is running, pid 20053
[26-Mar-2013 15:57:00] NOTICE: ready to handle connections
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20054 exited with code 0 after 92.745193 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20324 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20324 exited with code 0 after 0.005245 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20325 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20325 exited with code 0 after 0.005121 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20326 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20326 exited with code 0 after 0.005202 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20327 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20327 exited with code 0 after 0.005543 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20328 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20328 exited with code 0 after 0.004935 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20329 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20329 exited with code 0 after 0.005255 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20330 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20330 exited with code 0 after 0.005239 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20331 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20331 exited with code 0 after 0.005134 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20332 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20332 exited with code 0 after 0.005162 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20333 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20333 exited with code 0 after 0.004950 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20334 started
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20334 exited with code 0 after 0.005066 seconds
from start
[26-Mar-2013 15:58:33] NOTICE: [pool storage] child 20335 started
............
............
------------------------------------------------------------------------
[2012-10-25 13:57:40] adrian dot siminiceanu at gmail dot com
Hello,
I have the same behavior on my test machine using Red Hat Enterprise Linux Server release 5.3
(Tikanga) Update 3 using the following:
- nginx-1.2.4-1.ngx.x86_64
- php-fpm-5.3.10-2.x86_64 (built from the github php-src tag 5.1.30 - https://github.com/php/php-src/tree/php-5.3.10)
The php-fpm configuration is the following:
[www]
listen = /tmp/fastcgi.socket
;listen.backlog = -1
listen.allowed_clients = 127.0.0.1
;listen.owner = nobody
;listen.group = nobody
;listen.mode = 0666
user = apache
group = apache
pm = dynamic
pm.max_children = 300
pm.start_servers = 100
pm.min_spare_servers = 100
pm.max_spare_servers = 300
pm.max_requests = 500
;pm.status_path = /status
;ping.path = /ping
;ping.response = pong
;request_terminate_timeout = 0
;request_slowlog_timeout = 0
;slowlog = /var/log/php-fpm.log.slow
;rlimit_files = 1024
;rlimit_core = 0
;chroot =
;chdir = /var/www
;catch_workers_output = yes
;env[HOSTNAME] = $HOSTNAME
;env[PATH] = /usr/local/bin:/usr/bin:/bin
;env[TMP] = /tmp
;env[TMPDIR] = /tmp
;env[TEMP] = /tmp
;php_admin_value[sendmail_path] = /usr/sbin/sendmail -t -i -f www@my.domain.com
;php_flag[display_errors] = off
php_admin_value[error_log] = /var/log/php-fpm/www-error.log
php_admin_flag[log_errors] = on
;php_admin_value[memory_limit] = 32M
I am receiving at a rate of over 250/300 requests per seconds and for some reasons the number of
opened fd are increasing at a very high
rate. There is only one PHP script executed for each request that is not doing anything fancy and
that is really fast in doing what it
supposed to do.
If I look at the one of the php-fpm processes on the platform (e.g. pid = 12258) I can see the
following in /proc/<pid>/smaps:
2b9cbbb49000-2b9cbbb4a000 rw-s 00000000 00:09 346827919 /dev/zero (deleted)
Size: 4 kB
Rss: 4 kB
Shared_Clean: 0 kB
Shared_Dirty: 4 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Swap: 0 kB
2b9cbbb4a000-2b9cbbb4b000 rw-s 00000000 00:09 346827920 /dev/zero (deleted)
Size: 4 kB
Rss: 4 kB
Shared_Clean: 0 kB
Shared_Dirty: 4 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Swap: 0 kB
2b9cbbb4b000-2b9cbbb4c000 rw-s 00000000 00:09 346827921 /dev/zero (deleted)
Size: 4 kB
Rss: 4 kB
Shared_Clean: 0 kB
Shared_Dirty: 4 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Swap: 0 kB
2b9cbbb4c000-2b9cbbb4d000 rw-s 00000000 00:09 346827922 /dev/zero (deleted)
Size: 4 kB
Rss: 4 kB
Shared_Clean: 0 kB
Shared_Dirty: 4 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Swap: 0 kB
2b9cbbb4d000-2b9cbbb4e000 rw-s 00000000 00:09 346827923 /dev/zero (deleted)
Size: 4 kB
Rss: 4 kB
Shared_Clean: 0 kB
Shared_Dirty: 4 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Swap: 0 kB
The number of opened fd is really high and does not gow down when things calm down on the machine or
even when the php-fpm processes are
dyeing.
root@bench:/etc/php-fpm.d # ps aux | grep php-fpm | wc -l
134
root@bench:/etc/php-fpm.d # lsof | grep php-fpm | grep DEL | wc -l
40299
root@bench:/etc/php-fpm.d # lsof | grep php-fpm | wc -l
53270
root@bench6 [P/S] :/etc/php-fpm.d # /etc/init.d/php-fpm restart
Stopping php-fpm: [ OK ]
Starting php-fpm: [ OK ]
root@bench:/etc/php-fpm.d # ps aux | grep php-fpm | wc -l
102
root@bench:/etc/php-fpm.d # lsof | grep php-fpm | grep DEL | wc -l
30603
root@bench:/etc/php-fpm.d # lsof | grep php-fpm | wc -l
38970
As you see, even after a restart of the php-fpm daemon the DEL fd are not removed.
------------------------------------------------------------------------
[2012-06-23 01:03:41] dzambonini at names dot co dot uk
I can confirm that we are also experiencing this issue on a variety of platforms; for example:
nginx/0.8.54 (CentOS 5.8) w/ php-5.3.8, and Apache/2.2.5 (CentOS 6.2) mod_fastcgi/2.4.6 w/
php-5.3.14. Number of file descriptors in use at the time is only approx 300, well beneath any
limits. Again, catch_workers_output = no appears to prevent it appearing. Debug gives a little more
information:
[22-Jun-2012 12:20:36.849721] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 2
events
[22-Jun-2012 12:20:36.849766] DEBUG: pid 34148, fpm_got_signal(), line 72: received SIGCHLD
[22-Jun-2012 12:20:36.849831] NOTICE: pid 34148, fpm_children_bury(), line 252: [pool cpanel] child
34177 exited with code 0 after 84.142933 seconds from start
[22-Jun-2012 12:20:36.850989] NOTICE: pid 34148, fpm_children_make(), line 421: [pool cpanel] child
34960 started
[22-Jun-2012 12:20:36.851041] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 1
events
[22-Jun-2012 12:20:36.857710] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 2
events
[22-Jun-2012 12:20:36.857755] DEBUG: pid 34148, fpm_got_signal(), line 72: received SIGCHLD
[22-Jun-2012 12:20:36.857782] NOTICE: pid 34148, fpm_children_bury(), line 252: [pool cpanel] child
34960 exited with code 0 after 0.006813 seconds from start
[22-Jun-2012 12:20:36.858987] NOTICE: pid 34148, fpm_children_make(), line 421: [pool cpanel] child
34961 started
[22-Jun-2012 12:20:36.859029] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 1
events
[22-Jun-2012 12:20:36.865308] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 2
events
[22-Jun-2012 12:20:36.865367] DEBUG: pid 34148, fpm_got_signal(), line 72: received SIGCHLD
[22-Jun-2012 12:20:36.865393] NOTICE: pid 34148, fpm_children_bury(), line 252: [pool cpanel] child
34961 exited with code 0 after 0.006422 seconds from start
[22-Jun-2012 12:20:36.866606] NOTICE: pid 34148, fpm_children_make(), line 421: [pool cpanel] child
34962 started
[22-Jun-2012 12:20:36.866649] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 1
events
[22-Jun-2012 12:20:36.872867] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 2
events
[22-Jun-2012 12:20:36.872909] DEBUG: pid 34148, fpm_got_signal(), line 72: received SIGCHLD
[22-Jun-2012 12:20:36.872932] NOTICE: pid 34148, fpm_children_bury(), line 252: [pool cpanel] child
34962 exited with code 0 after 0.006343 seconds from start
[22-Jun-2012 12:20:36.874164] NOTICE: pid 34148, fpm_children_make(), line 421: [pool cpanel] child
34963 started
[22-Jun-2012 12:20:36.874208] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 1
events
[22-Jun-2012 12:20:36.880463] DEBUG: pid 34148, fpm_event_loop(), line 409: event module triggered 2
events
[22-Jun-2012 12:20:36.880528] DEBUG: pid 34148, fpm_got_signal(), line 72: received SIGCHLD
(etc. repeating SIGCHLD in same pattern)
------------------------------------------------------------------------
The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at
https://bugs.php.net/bug.php?id=61558
--
Edit this bug report at https://bugs.php.net/bug.php?id=61558&edit=1