why is php-fpm spawning and destroying hundreds of children per second with no server load?

Question

The php7.0-fpm.log is showing hundreds of children being spawned per second, then being immediately destroyed. This is happening non-stop. The log looks like this:

[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4980 started
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4978 exited with code 0 after 0.014658 seconds from start
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4981 started
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4980 exited with code 0 after 0.014354 seconds from start
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4982 started
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4979 exited with code 0 after 0.015170 seconds from start
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4983 started
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4981 exited with code 0 after 0.014709 seconds from start
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4984 started
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4982 exited with code 0 after 0.014741 seconds from start
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4985 started
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4983 exited with code 0 after 0.014727 seconds from start
[09-Mar-2017 02:58:25] NOTICE: [pool www] child 4986 started

Settings from /etc/php/7.0/fpm/php-fpm.conf:

pid = /run/php/php7.0-fpm.pid
error_log = /var/log/php7.0-fpm.log
include=/etc/php/7.0/fpm/pool.d/*.conf

Settings from /etc/php/7.0/fpm/pool.d/www.conf:

pm = dynamic
pm.max_children = 5
pm.start_servers = 2
pm.min_spare_servers = 1
pm.max_spare_servers = 3
;pm.process_idle_timeout = 10s;
;pm.max_requests = 500
catch_workers_output = yes
php_flag[display_errors] = on
php_admin_value[error_log] = /var/log/phperrors.log
php_admin_flag[log_errors] = on

All other lines are commented out with ; (default settings). This is Ubuntu 16.04, using the default packages. PHP and Nginx versions are as follows:

php-fpm7.0 -v
PHP 7.0.13-0ubuntu0.16.04.1 (fpm-fcgi)
Copyright (c) 1997-2016 The PHP Group
Zend Engine v3.0.0, Copyright (c) 1998-2016 Zend Technologies
    with Zend OPcache v7.0.13-0ubuntu0.16.04.1, Copyright (c) 1999-2016, by Zend Technologies

nginx -v
nginx version: nginx/1.10.0 (Ubuntu)

No tuning was done (other than enabling the logging). This server is not yet deployed to production, so there is no user load.

Why is php-fpm spawning and immediately destroying hundreds of children per second? Is this a misconfiguration, or does Ubuntu 16.04 ship with a buggy php-fpm version?

score 7 · Accepted Answer · 2017-03-09T09:16:21.453

7

Neither misconfiguration nor buggy version. In fact, there is nothing to be worried about.

The reason your processes are exiting and respawning that fast is that you are using the default value for pm.max_requests in your php-fpm pool configuration file as it's commented via a semi-colon ; symbol. To understand what pm.max_requests parameter stands for you can read the following description taken from the default configuration:

pm.max_requests = int

The number of requests each child process should execute before respawning. This can be useful to work around memory leaks in 3rd party libraries. For endless request processing specify '0'. Equivalent to PHP_FCGI_MAX_REQUESTS. Default value: 0.

And yours is 0 since it's commented. You can set it to something like 100-500 (depending on your needs) so as to have your php-fpm recycling the process after processing that amount of requests.

By the way, you should note that these messages in your log file is only informational and there is nothing wrong, so don't you worry. These log entries can be avoided by using the value of warning instead of notice for the log_level parameter in php-fpm.conf. It is almost showing everything - a bit less than debug level - since the default value is set to notice.

Taken from the default configuration:

log_level = string

Error log level. Possible values: alert, error, warning, notice, debug. Default value: notice.

Good Luck

edited Mar 09 '17 at 09:16

answered Mar 09 '17 at 09:06

1

It was a problem because the log file was eating 20G of disk space per week. I wanted to fix the underlying cause rather than suppress the logging issue. I set `pm.max_requests` to 500 and the log seems to be much quieter now. – Nick Mar 09 '17 at 10:55
2

@Nick well, first of all, I'm happy that I could help you with the answer. I got your problem, so I should ask why don't you manage your log files or set some limitations for your log files size? You can easily use utilities like `logrotate`. I guess they will help you a lot. – Mar 09 '17 at 11:04
1

`logrotate` is setup, `php-fpm` was just writing more data to the log than there was disk on the server faster than `logrotate` could rotate and delete them. – Nick Mar 09 '17 at 11:09
@Nick Got you mate, so yes the best thing to do is what is said in the answer. Good luck mate. – Mar 09 '17 at 11:12
I think the problem is that the default setting seems to be bizarre - an apparently *idle* fpm will keep spinning like this until stopped. – Josip Rodin Aug 29 '17 at 14:31
1

The documentation you quoted seems not to agree with your answer. Endless processing should be the best case, not the worst. On the other hand, when a setting of 500 helped, it looks like the setting was changed somewhere or the help about the default is wrong. – allo Oct 02 '17 at 14:41
@allo I had the same doubt, why are the processes respawning if the default is 0, meaning they will not respawn? – JorgeeFG Jan 28 '22 at 13:13

Josip Rodin · Answer 2 · 2017-10-02T13:39:01.583

This has been happening on one of my servers with Ubuntu 14 (PHP 5) and 16 (PHP 7). With the earlier version, there was some delay, but with the latest version, as soon as a single problematic request is served by the FPM process it goes wild.

I noticed that the problematic kind of requests do happen to exec stuff like in https://stackoverflow.com/questions/44400072/php-fpm-forever-respawning-children-when-executing-uglifycss but I still don't see how that should cause this. It seems to be closely correlated with executing stuff in the background (with the & operator).

I can't offer an actual solution, merely my fugly workaround script that runs from cron:

#!/bin/sh -e

v=${1:-7.0}
poolname=${2:-www}

# requires Restart=always and KillMode=process in /lib/systemd/system/php7.0-fpm.service!
retire_fpm() {
  logger -p user.crit -t $0 "$(sudo pkill -e php$v-fpm || sudo pkill -e php-fpm$v || echo "aiee, could not find php fpm version $v to retire" >&2)"
}

if sudo initctl version 2>/dev/null; then # upstart
  logdir=/var/log
  logfile=$logdir/upstart/php$v-fpm.log
else
  logdir=/var/log
  logfile=$logdir/php$v-fpm.log
fi

logfile_huge=$(test -e $logfile && find $logfile -size +200M || true)
if [ -n "$logfile_huge" ]; then
  logger -p user.crit -t $0 "demolishing $logfile to prevent the partition from filling up"
  cp /dev/null $logfile
fi

rotated_logfile_huge=$(test -e $logfile.1 && find $logfile.1 -size +200M || true)
if [ -n "$rotated_logfile_huge" ]; then
  logger -p user.crit -t $0 "demolishing $logfile.1 to prevent the partition from filling up"
  cp /dev/null $logfile.1
fi

if [ ! -e $logfile ]; then
  if ! df -P $logdir/ | awk '/^\// && $5+0 > 50 { exit(1) }'; then
    logger -p user.crit -t $0 "initiating php$v-fpm termination (init will restart it) because there is no $logfile yet the partition is filling up"
  else
    logger -p user.crit -t $0 "initiating php$v-fpm termination (init will restart it) because there is no $logfile, something went awry"
  fi
  retire_fpm
  exit
fi

logfile_grew=$(find $logfile -size +5M || true)

if [ -z "$logfile_grew" ]; then
  exit 0
fi

# 5 lines: handle recovery: one started line, one exited line, three post-signal lines
recent_fast_respawns=$(tail -5 $logfile | egrep -c ' NOTICE: .pool '$poolname'. child .+ exited with code 0 after 0....... seconds from start')

if [ "$recent_fast_respawns" -le 1 ]; then
  logger -p user.notice -t $0 "php$v-fpm log $logfile indicates a lot of recent activity, but only $recent_fast_respawns recent fast respawns, leaving it be"
  exit 0
fi

logger -p user.crit -t $0 "initiating php$v-fpm termination (init will restart it) because $logfile indicates $recent_fast_respawns recent fast respawns"
retire_fpm

This should never have existed... and yet I've been updating it over time. <sigh>

why is php-fpm spawning and destroying hundreds of children per second with no server load?

2 Answers2