Bug #61558 [Com]: Runaway spawning of children after pipe error

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'd recommend being inspired by aka copying the behaviour of Supervisord. http://supervisord.org/subprocess.html Basically it does what it probably the best behaviour of: i) If child processes exist too quickly, put them in a 'back off' state, to rate limit the number of processes attempting to be started. ii) If they still fail to start after a reasonable number of retries stop trying to start it for now. Admittedly, sounds like a big task for something that should be a rare event. Previous Comments: ------------------------------------------------------------------------ [2014-07-25 09:06:12] tony2001@php.net Ok, so FPM basically starts the children, but they die immediately (for a reason) and FPM master process starts the new ones. I can think of adding some option that would limit the number of children spawned per second, or probably abort the whole process if N children were created in the last N seconds, but that kind of solution looks quite hacky to me. ------------------------------------------------------------------------ [2014-07-24 19:44:00] Danack at basereality dot com 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. ------------------------------------------------------------------------ [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