php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #71651 PHP-FPM crashes when having too many users while doing a heavy job
Submitted: 2016-02-23 15:38 UTC Modified: 2017-12-23 12:13 UTC
Votes:3
Avg. Score:4.3 ± 0.9
Reproduced:2 of 2 (100.0%)
Same Version:2 (100.0%)
Same OS:-1 (-50.0%)
From: theo dot tzaferis at active-value dot de Assigned:
Status: Duplicate Package: FPM related
PHP Version: 5.6.18 OS: Debian GNU/Linux 7.9 (wheezy)
Private report: No CVE-ID: None
View Developer Edit
Welcome! If you don't have a Git account, you can't do anything here.
If you reported this bug, you can edit this bug over here.
(description)
Block user comment
Status: Assign to:
Package:
Bug Type:
Summary:
From: theo dot tzaferis at active-value dot de
New email:
PHP Version: OS:

 

 [2016-02-23 15:38 UTC] theo dot tzaferis at active-value dot de
Description:
------------
I have a Server running Apache/2.2.22 (Debian), PHP 5.6.17 as FPM and MySQL 5.6.25.

The project runs using a CMS called Redaxo (I don't think it's that important, but I'll tell ya anyway). In Redaxo there are some functions which take some time (e.g. deleting cache and rebuilding it takes 1-2 minutes). In this time, when other users come on the website FPM crashes with a `500 Internal Server Error` and I have to reload the page multiple times until the Server Error disappears and the process is done.

I noticed that this only will happen if too many users are on the site on the same time and only when heavy operations are done. 

10 users at the same time just surfing = No Problem  
10 users at the same time just surfing, while cache deletion = 500 Error for everyone.

I checked this by disallowing the website for everyone except me (.htaccess deny/allow with ip). Then I did the heavy operation and had no problem. As soon as multiple people were on the site again, the problem was there again.

What could it be? What information do you need from me?

These values are set (not commented) in the `php-fpm.conf`
 
    [global]
    pid = /run/php5-fpm.pid
    error_log = /var/log/php5-fpm.log
    emergency_restart_threshold = 0
    include=/etc/php5/fpm/pool.d/*.conf

These values are set (not commented) in the project specific `fpm.conf`

    [projectname]
    user = projectname
    group = projectname
    
    listen = /var/run/php5-fpm-projectname.sock
    listen.owner = projectname
    listen.group = projectname
    listen.mode = 0660
    
    pm = dynamic
    pm.max_children = 150
    pm.start_servers = 10
    pm.min_spare_servers = 10
    pm.max_spare_servers = 30
    
    chdir = /
    
    php_value[upload_max_filesize] = 128M
    php_value[max_post_size] = 128M
    php_value[max_execution_time] = 180
    php_value[memory_limit] = 256M

  
    
The script when it fails does much with MySQL and File creation if it helps? But it's pretty big, so I'm not sure if I should post it here? Or if it is even the problem? 

The apache error log says either this

    [Tue Feb 09 10:54:01 2016] [error] [client {IP}] (104)Connection reset by peer: FastCGI: comm with server "/fcgi-bin-php5-fpm-projectnmae" aborted: read failed
    [Tue Feb 09 10:54:01 2016] [error] [client {IP}] FastCGI: incomplete headers (0 bytes) received from server "/fcgi-bin-php5-fpm-projectnmae"

or this

    [Tue Feb 09 11:00:46 2016] [error] [client {IP}] FastCGI: incomplete headers (0 bytes) received from server "/fcgi-bin-php5-fpm-projectname"
    [Tue Feb 09 11:00:48 2016] [error] [client {IP}] (104)Connection reset by peer: FastCGI: comm with server "/fcgi-bin-php5-fpm-projectname" aborted: read failed

    
The `fpm-log` says the following. Always different timings of course

    [10-Feb-2016 09:40:59] WARNING: [pool projectname] child 10970 exited on signal 7 (SIGBUS) after 50.186611 seconds from start
    [10-Feb-2016 09:40:59] NOTICE: [pool projectname] child 11092 started

Sometimes there's a warning like this in it

    [09-Feb-2016 11:00:41] WARNING: [pool projectname] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
    [09-Feb-2016 11:00:42] WARNING: [pool projectname] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 0 idle, and 7 total children

Here are some more debug information

    [18-Feb-2016 17:42:01] WARNING: [pool projectname] child 9088 exited on signal 7 (SIGBUS) after 70.130564 seconds from start
    [18-Feb-2016 17:42:01] NOTICE: [pool projectname] child 9205 started
    [18-Feb-2016 17:43:55] WARNING: [pool projectname] child 9099 said into stderr: "NOTICE: PHP message: PHP Notice:  Undefined offset: 1181 in /var/www/projectname/htdocs/redaxo/include/classes/class.ooarticle.inc.php on line 44"
    [18-Feb-2016 17:43:55] WARNING: [pool projectname] child 9099 said into stderr: "NOTICE: PHP message: PHP Warning:  Invalid argument supplied for foreach() in /var/www/projectname/htdocs/redaxo/include/classes/class.ooredaxo.inc.php on line 134"
    [18-Feb-2016 17:43:55] WARNING: [pool projectname] child 9099 exited on signal 7 (SIGBUS) after 183.838886 seconds from start
    [18-Feb-2016 17:43:55] NOTICE: [pool projectname] child 9330 started
    [18-Feb-2016 17:44:00] WARNING: [pool projectname] child 9101 exited on signal 7 (SIGBUS) after 188.987954 seconds from start
    [18-Feb-2016 17:44:00] NOTICE: [pool projectname] child 9336 started


Here is content of the /var/log/php-5fpm.log

    [18-Feb-2016 17:00:40] WARNING: [pool projectname] child 5786 exited on signal 7 (SIGBUS - core dumped) after 147.426805 seconds from start
    [18-Feb-2016 17:00:40] NOTICE: [pool projectname] child 6037 started
    [18-Feb-2016 17:09:13] WARNING: [pool projectname] child 6512 exited on signal 7 (SIGBUS - core dumped) after 126.387640 seconds from start
    [18-Feb-2016 17:09:13] NOTICE: [pool projectname] child 6782 started
    [18-Feb-2016 17:09:22] WARNING: [pool projectname] child 6514 exited on signal 7 (SIGBUS - core dumped) after 135.431805 seconds from start
    [18-Feb-2016 17:09:22] NOTICE: [pool projectname] child 6820 started

Active mods:

    10-mysqlnd.ini -> ../../mods-available/mysqlnd.ini
    10-pdo.ini -> ../../mods-available/pdo.ini
    20-gd.ini -> ../../mods-available/gd.ini
    20-mysql.ini -> ../../mods-available/mysql.ini
    20-mysqli.ini -> ../../mods-available/mysqli.ini
    20-pdo_mysql.ini -> ../../mods-available/pdo_mysql.ini
    20-readline.ini -> ../../mods-available/readline.ini


Coredump

root@X-1080-8:/tmp# gdb /usr/sbin/php5-fpm /tmp/coredump-php5-fpm.6514
	GNU gdb (GDB) 7.4.1-debian
	Copyright (C) 2012 Free Software Foundation, Inc.
	License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
	This is free software: you are free to change and redistribute it.
	There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
	and "show warranty" for details.
	This GDB was configured as "x86_64-linux-gnu".
	For bug reporting instructions, please see:
	<http://www.gnu.org/software/gdb/bugs/>...
	Reading symbols from /usr/sbin/php5-fpm...(no debugging symbols found)...done.
	[New LWP 6514]

	warning: Can't read pathname for load map: Input/output error.
	[Thread debugging using libthread_db enabled]
	Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
	Core was generated by `php-fpm: pool projectname                                                  '.
	Program terminated with signal 7, Bus error.
	#0  0x00000000006c22d5 in lex_scan ()
	(gdb) bt
	#0  0x00000000006c22d5 in lex_scan ()
	#1  0x00000000006e2220 in zendlex ()
	#2  0x00000000006bb1d9 in zendparse ()
	#3  0x00000000006c0d23 in compile_file ()
	#4  0x00000000006e8a8a in dtrace_compile_file ()
	#5  0x0000000000568c4e in ?? ()
	#6  0x00000000006c0ed0 in compile_filename ()
	#7  0x000000000079edfb in ?? ()
	#8  0x0000000000763418 in execute_ex ()
	#9  0x00000000006e8b0d in dtrace_execute_ex ()
	#10 0x000000000079e8f8 in ?? ()
	#11 0x0000000000763418 in execute_ex ()
	#12 0x00000000006e8b0d in dtrace_execute_ex ()
	#13 0x000000000079e8f8 in ?? ()
	#14 0x0000000000763418 in execute_ex ()
	#15 0x00000000006e8b0d in dtrace_execute_ex ()
	#16 0x000000000079e8f8 in ?? ()
	#17 0x0000000000763418 in execute_ex ()
	#18 0x00000000006e8b0d in dtrace_execute_ex ()
	#19 0x000000000079e8f8 in ?? ()
	#20 0x0000000000763418 in execute_ex ()
	#21 0x00000000006e8b0d in dtrace_execute_ex ()
	#22 0x000000000079e8f8 in ?? ()
	#23 0x0000000000763418 in execute_ex ()
	#24 0x00000000006e8b0d in dtrace_execute_ex ()
	#25 0x000000000079e8f8 in ?? ()
	#26 0x0000000000763418 in execute_ex ()
	#27 0x00000000006e8b0d in dtrace_execute_ex ()
	#28 0x000000000079e8f8 in ?? ()
	#29 0x0000000000763418 in execute_ex ()
	#30 0x00000000006e8b0d in dtrace_execute_ex ()
	#31 0x000000000079e8f8 in ?? ()
	#32 0x0000000000763418 in execute_ex ()
	#33 0x00000000006e8b0d in dtrace_execute_ex ()
	#34 0x000000000079e8f8 in ?? ()
	#35 0x0000000000763418 in execute_ex ()
	#36 0x00000000006e8b0d in dtrace_execute_ex ()
	#37 0x000000000079e8f8 in ?? ()
	#38 0x0000000000763418 in execute_ex ()
	#39 0x00000000006e8b0d in dtrace_execute_ex ()
	#40 0x00000000006ea846 in zend_call_function ()
	#41 0x0000000000618154 in zif_call_user_func ()
	#42 0x00000000006e8c39 in dtrace_execute_internal ()
	#43 0x000000000079e2c1 in ?? ()
	#44 0x0000000000763418 in execute_ex ()
	#45 0x00000000006e8b0d in dtrace_execute_ex ()
	#46 0x000000000079e8f8 in ?? ()
	#47 0x0000000000763418 in execute_ex ()
	#48 0x00000000006e8b0d in dtrace_execute_ex ()
	#49 0x000000000079e8f8 in ?? ()
	#50 0x0000000000763418 in execute_ex ()
	#51 0x00000000006e8b0d in dtrace_execute_ex ()
	#52 0x000000000079fb64 in ?? ()
	#53 0x0000000000763418 in execute_ex ()
	#54 0x00000000006e8b0d in dtrace_execute_ex ()
	#55 0x00000000006fb468 in zend_execute_scripts ()
	#56 0x0000000000696852 in php_execute_script ()
	#57 0x0000000000473b62 in main ()


Additional information:


I already checked the process list of the MySQL database while the proccess is happening. I have many requests, but their state is "Creating sort index". Nothing like "Waiting for query cache lock"

I have no full CPU usage and I'm using an SSD. Nothing is on 100% usage, so nothing is too overallocated. 

Someone showed me this bug report: https://bugs.php.net/bug.php?id=52752

But in this bug report the bug only happens when doing file_put_contents and afterwards including/requiring the file. We use file_put_contents and file_get_contents and file_exists. No include/require







Test script:
---------------
I think it starts here, because when I save a new meta info field I'm getting the error


https://github.com/redaxo/redaxo4/blob/master/redaxo/include/addons/metainfo/classes/class.rex_table_expander.inc.php#L206

Expected result:
----------------
200 OK and the processes finish

Actual result:
--------------
500 Internal Server Error and I have to reload the page until it doesn't happen anymore

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2016-02-23 15:39 UTC] theo dot tzaferis at active-value dot de
I wrote that we are using PHP 5.6.17, but we are actually using 5.6.18
 [2017-12-23 12:13 UTC] nikic@php.net
-Status: Open +Status: Duplicate
 [2017-12-23 12:13 UTC] nikic@php.net
This is very likely a duplicate of bug #52752.
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved.
Last updated: Thu Dec 12 14:01:28 2024 UTC