PHP :: Bug #61558 :: Runaway spawning of children after pipe error

Bug #61558

Runaway spawning of children after pipe error

Submitted:

2012-03-29 20:28 UTC

Modified:

2022-09-28 18:01 UTC

Votes:	55
Avg. Score:	4.5 ± 0.8
Reproduced:	53 of 53 (100.0%)
Same Version:	24 (45.3%)
Same OS:	18 (34.0%)

From:

phpbug2012 at tgabber dot mine dot nu

Assigned:

bukka (profile)

Status:

Closed

Package:

FPM related

PHP Version:

5.3.10

OS:

Debian Linux

Private report:

CVE-ID:

None

View Developer Edit

[2012-03-29 20:28 UTC] phpbug2012 at tgabber dot mine dot nu

Description:
------------
Relevant software versions

Linux 2.6.32-5-amd64
Server Version: Apache/2.2.16 (Debian) DAV/2 mod_fastcgi/2.4.6
PHP Version 5.3.10-1~dotdeb.1
APC Version	3.1.9

Background

This is a lightly-loaded webserver running around 40 virtual hosts that experiences occasional traffic spikes. Around 20 virtual hosts use php and have one fpm pool each to run php under their own user, configured as ondemand so that they have no fpm processes running when they are not serving pages. Generally there are between 1 and 5 fpm processes running in total at any one time, rising to maybe 20 to 30 when a spike of traffic comes in.

Error

I became aware of the problem after a service monitor reported that websites were no longer being served. Checking, I found that that php-fpm had crashed. Time since the last restart of php-fpm when the error occured was about 2 days 4 hours, with around 2.5million php requests served. The APC cache of 128Mb was about three-quarters full.

Looking back through the logs, this is what I found. The problem appears to start at 18:55:32 when php-fpm was unable to read a pipe. I have no idea what caused this initial error, looking back through other logs I could not see any abnormal web requests around this time.

Mar 24 18:55:32 banana php-fpm[21906]: [ERROR] unable to read what child say: Bad file descriptor (9)
Mar 24 18:55:32 banana php-fpm[21906]: [ERROR] unable to read what child say: Bad file descriptor (9)

There were no further fpm messages in the log until those shown below. This is the most worrying aspect of this bug as basically fpm seems to have gone into meltdown, continually spawning a process (and using almost all available cpu).


Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22229 exited with code 0 after 0.002001 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22230 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22230 exited with code 0 after 0.001790 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22231 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22231 exited with code 0 after 0.001694 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22232 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22232 exited with code 0 after 0.001692 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22233 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22233 exited with code 0 after 0.001685 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22234 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22234 exited with code 0 after 0.001683 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22235 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22235 exited with code 0 after 0.001659 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22236 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22236 exited with code 0 after 0.001677 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22237 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22237 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22238 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22238 exited with code 0 after 0.001661 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22239 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22239 exited with code 0 after 0.001653 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22240 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22240 exited with code 0 after 0.001667 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22241 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22241 exited with code 0 after 0.001638 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22242 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22242 exited with code 0 after 0.001669 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22243 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22243 exited with code 0 after 0.001660 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22244 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22244 exited with code 0 after 0.001664 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22245 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22245 exited with code 0 after 0.001644 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22246 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22246 exited with code 0 after 0.001671 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22247 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22247 exited with code 0 after 0.001639 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22248 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22248 exited with code 0 after 0.001669 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22249 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22249 exited with code 0 after 0.001651 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22250 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22250 exited with code 0 after 0.001659 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22251 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22251 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22252 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22252 exited with code 0 after 0.001654 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22253 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22253 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22254 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22254 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22255 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22255 exited with code 0 after 0.001633 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22256 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22256 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22257 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22257 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22258 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22258 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22259 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22259 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22260 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22260 exited with code 0 after 0.001660 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22261 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22261 exited with code 0 after 0.001643 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22262 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22262 exited with code 0 after 0.001660 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22263 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22263 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22264 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22264 exited with code 0 after 0.001659 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22265 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22265 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22266 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22266 exited with code 0 after 0.001684 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22267 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22267 exited with code 0 after 0.001653 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22268 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22268 exited with code 0 after 0.001659 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22269 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22269 exited with code 0 after 0.001641 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22270 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22270 exited with code 0 after 0.001665 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22271 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22271 exited with code 0 after 0.001631 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22272 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22272 exited with code 0 after 0.001655 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22273 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22273 exited with code 0 after 0.001643 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22274 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22274 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22275 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22275 exited with code 0 after 0.001653 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22276 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22276 exited with code 0 after 0.001658 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22277 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22277 exited with code 0 after 0.001640 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22278 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22278 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22279 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22279 exited with code 0 after 0.001653 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22280 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22280 exited with code 0 after 0.001701 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22281 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22281 exited with code 0 after 0.001660 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22282 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22282 exited with code 0 after 0.007454 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22283 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22283 exited with code 0 after 0.001857 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22284 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22284 exited with code 0 after 0.001721 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22285 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22285 exited with code 0 after 0.001697 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22286 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22286 exited with code 0 after 0.001675 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22287 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22287 exited with code 0 after 0.001684 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22288 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22288 exited with code 0 after 0.001659 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22289 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22289 exited with code 0 after 0.001651 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22290 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22290 exited with code 0 after 0.001653 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22291 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22291 exited with code 0 after 0.001650 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22292 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22292 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22293 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22293 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22294 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22294 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22295 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22295 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22296 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22296 exited with code 0 after 0.001665 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22297 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22297 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22298 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22298 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22299 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22299 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22300 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22300 exited with code 0 after 0.001639 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22301 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22301 exited with code 0 after 0.001637 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22302 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22302 exited with code 0 after 0.001640 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22303 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22303 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22304 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22304 exited with code 0 after 0.001658 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22305 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22305 exited with code 0 after 0.001637 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22306 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22306 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22307 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22307 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22308 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22308 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22309 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22309 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22310 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22310 exited with code 0 after 0.001642 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22311 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22311 exited with code 0 after 0.001654 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22312 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22312 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22313 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22313 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22314 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22314 exited with code 0 after 0.001640 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22315 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22315 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22316 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22316 exited with code 0 after 0.001644 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22317 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22317 exited with code 0 after 0.001650 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22318 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22318 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22319 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22319 exited with code 0 after 0.001643 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22320 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22320 exited with code 0 after 0.001641 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22321 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22321 exited with code 0 after 0.001666 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22322 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22322 exited with code 0 after 0.001643 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22323 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22323 exited with code 0 after 0.001680 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22324 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22324 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22325 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22325 exited with code 0 after 0.001656 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22326 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22326 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22327 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22327 exited with code 0 after 0.001659 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22328 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22328 exited with code 0 after 0.001656 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22329 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22329 exited with code 0 after 0.001684 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22330 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22330 exited with code 0 after 0.001638 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22331 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22331 exited with code 0 after 0.001656 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22332 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22332 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22333 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22333 exited with code 0 after 0.001650 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22334 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22334 exited with code 0 after 0.001638 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22335 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22335 exited with code 0 after 0.001650 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22336 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22336 exited with code 0 after 0.001636 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22337 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22337 exited with code 0 after 0.001654 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22338 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22338 exited with code 0 after 0.001638 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22339 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22339 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22340 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22340 exited with code 0 after 0.001639 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22341 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22341 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22342 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22342 exited with code 0 after 0.001637 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22343 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22343 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22344 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22344 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22345 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22345 exited with code 0 after 0.001654 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22346 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22346 exited with code 0 after 0.001632 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22347 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22347 exited with code 0 after 0.001644 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22348 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22348 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22349 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22349 exited with code 0 after 0.001644 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22350 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22350 exited with code 0 after 0.001651 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22351 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22351 exited with code 0 after 0.001658 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22352 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22352 exited with code 0 after 0.001634 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22353 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22353 exited with code 0 after 0.001654 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22354 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22354 exited with code 0 after 0.001633 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22355 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22355 exited with code 0 after 0.001650 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22356 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22356 exited with code 0 after 0.001640 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22357 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22357 exited with code 0 after 0.001656 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22358 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22358 exited with code 0 after 0.001632 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22359 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22359 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22360 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22360 exited with code 0 after 0.001635 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22361 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22361 exited with code 0 after 0.001637 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22362 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22362 exited with code 0 after 0.001628 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22363 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22363 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22364 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22364 exited with code 0 after 0.001631 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22365 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22365 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22366 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22366 exited with code 0 after 0.001630 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22367 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22367 exited with code 0 after 0.001642 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22368 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22368 exited with code 0 after 0.001641 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22369 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22369 exited with code 0 after 0.001649 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22370 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22370 exited with code 0 after 0.001637 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22371 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22371 exited with code 0 after 0.001689 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22372 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22372 exited with code 0 after 0.001634 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22373 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22373 exited with code 0 after 0.001648 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22374 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22374 exited with code 0 after 0.001636 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22375 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22375 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22376 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22376 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22377 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22377 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22378 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22378 exited with code 0 after 0.001637 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22379 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22379 exited with code 0 after 0.001656 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22380 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22380 exited with code 0 after 0.001628 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22381 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22381 exited with code 0 after 0.001655 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22382 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22382 exited with code 0 after 0.001646 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22383 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22383 exited with code 0 after 0.001652 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22384 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22384 exited with code 0 after 0.001676 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22385 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22385 exited with code 0 after 0.001651 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22386 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22386 exited with code 0 after 0.001636 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22387 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22387 exited with code 0 after 0.001647 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22388 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22388 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22389 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22389 exited with code 0 after 0.001640 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22390 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22390 exited with code 0 after 0.001636 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22391 started
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22391 exited with code 0 after 0.001645 seconds from start
Mar 24 18:56:48 banana php-fpm[21906]: [NOTICE] [pool ci] child 22392 started
Mar 24 18:56:49 banana php-fpm[21906]: [NOTICE] [pool ci] child 22392 exited with code 0 after 0.001638 seconds from start

Messages like his continued for nearly two minutes until php-fpm segfaulted (which is just as well, as I didn't get onto the server to clean up the mess for another 30 minutes). 

Mar 24 18:58:37 banana php-fpm[21906]: [NOTICE] [pool ci] child 947 exited with code 0 after 0.003013 seconds from start
Mar 24 18:58:37 banana php-fpm[21906]: [NOTICE] [pool ci] child 950 started
Mar 24 18:58:37 banana kernel: [4332778.033172] php5-fpm[21906]: segfault at 2 ip 0000000000000002 sp 00000000ffd50bec error 14 in php5-fpm[8048000+787000]

I had a quick look at the fpm source code and it would seem that if a child cannot read the initial request that it was spawned to handle it will exit almost immediately with code 0. The master, still seeing there is a request to handle spawns a new process and so on... Whilst it does not address the cause that a pipe became unreadable, the child ought to exit with a code other than zero under these circumstances so that the master process does not continually retry (and maybe php-fpm could restart itself?).

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports

[2012-05-23 13:26 UTC] fat@php.net

-Assigned To: +Assigned To: fat

[2012-05-23 18:30 UTC] fat@php.net

-Status: Assigned +Status: Feedback

[2012-05-23 18:30 UTC] fat@php.net

Not enough information was provided for us to be able
to handle this bug. Please re-read the instructions at
http://bugs.php.net/how-to-report.php

If you can provide more information, feel free to add it
to this bug and change the status back to "Open".

Thank you for your interest in PHP.


Does the error happened again since (is it reproductible) ? If so, It would be 
great to have a stacktrace of the last segfault.

Do you still have the error log? I'd like to see what was just before and after 
the "Bad file descriptor" lines.

Do you have, by any chances, reached any ulimit limitations (like number of open 
files) ? This could maybe explain the "Bad file descriptor" error (but not the 
others errors)

If you have any clue on how to reproduce the problem, it would be very useful to 
fix what seems to be an important bug to me.

thx a lot

[2012-05-23 22:34 UTC] phpbug2012 at tgabber dot mine dot nu

-Status: Feedback +Status: Assigned

[2012-05-23 22:34 UTC] phpbug2012 at tgabber dot mine dot nu

Hi,

The bug is not reproducible as such, however it has happened 3 more times with exactly the same symptoms, with uptimes for fpm varying from 2 days to 5 days. After this I changed the fpm pool configuration files to have catch_workers_output = no (I'd mistakenly thought that this had to be yes to have php errors logged to syslog) and the bug has not resurfaced so far (maximum uptime reached with this config 16 days).

I'm afraid I don't have anything else from the log files now other than what I included in the initial bug report. However I did thoroughly check the logs at the time and there were no other errors either from php or any other service.

There are no ulimits in force on the server and I doubt I ran out of file descriptors as checking /proc/sys/fs/file-nr just now shows only 2528 out of 392117 used.

I'm reluctant to change the config back to gather more information on the bug as this is a production server and the bug if it hits has a severe impact. I do have a backup machine (with the same config) that I could experiment on, but without knowing exactly how to trigger the bug and no real-world load I don't know how useful that would be.

[2012-06-23 01:03 UTC] 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)

[2012-10-25 13:57 UTC] 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.

[2013-05-23 13:44 UTC] 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
............
............

[2013-12-09 07:39 UTC] tony2001@php.net

-Assigned To: fat +Assigned To: tony2001

[2014-07-24 19:44 UTC] 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.

[2014-07-25 09:06 UTC] 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-25 13:07 UTC] Danack at basereality dot com

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.

[2015-08-03 03:25 UTC] kobenews at cox dot net

I think this issue is related to a bug I just posted. Same behavior where php-fpm restarts the process over and over again, causing php-fpm master to use 100% cpu. The test script is a little bit simpler, though requires exec() and running a SSH command using multiplexing.

https://bugs.php.net/bug.php?id=70185&edit=2

[2017-10-24 04:57 UTC] kalle@php.net

-Status: Assigned +Status: Analyzed -Assigned To: tony2001 +Assigned To:

[2022-09-28 18:01 UTC] bukka@php.net

-Status: Analyzed +Status: Assigned -Assigned To: +Assigned To: bukka

[2022-09-28 18:01 UTC] bukka@php.net

The actual issue was resolved a long time ago. We kept it open just as a reminder that we should do something about handling of a quick child crash in FPM master to not become unresponsive. I thought more about implementation of that and write it down to https://github.com/php/php-src/issues/9632 so closing this.

[2022-09-28 18:01 UTC] bukka@php.net

-Status: Assigned +Status: Closed

	php.net \| support \| documentation \| report a bug \| advanced search \| search howto \| statistics \| random bug \| login
go to bug id or search bugs for


Copyright © 2001-2024 The PHP Group All rights reserved.	Last updated: Wed Dec 04 19:01:32 2024 UTC