Bug #71651 [NEW]: PHP-FPM crashes when having too many users while doing a heavy job

From: theo dot tzaferis at active-value dot de Operating system: Debian GNU/Linux 7.9 (wheezy) PHP version: 5.6.18 Package: FPM related Bug Type: Bug Bug description:PHP-FPM crashes when having too many users while doing a heavy job 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 -- Edit bug report at https://bugs.php.net/bug.php?id=71651&edit=1 -- Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=71651&r=trysnapshot54 Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=71651&r=trysnapshot55 Try a snapshot (trunk): https://bugs.php.net/fix.php?id=71651&r=trysnapshottrunk Fixed in SVN: https://bugs.php.net/fix.php?id=71651&r=fixed Fixed in release: https://bugs.php.net/fix.php?id=71651&r=alreadyfixed Need backtrace: https://bugs.php.net/fix.php?id=71651&r=needtrace Need Reproduce Script: https://bugs.php.net/fix.php?id=71651&r=needscript Try newer version: https://bugs.php.net/fix.php?id=71651&r=oldversion Not developer issue: https://bugs.php.net/fix.php?id=71651&r=support Expected behavior: https://bugs.php.net/fix.php?id=71651&r=notwrong Not enough info: https://bugs.php.net/fix.php?id=71651&r=notenoughinfo Submitted twice: https://bugs.php.net/fix.php?id=71651&r=submittedtwice register_globals: https://bugs.php.net/fix.php?id=71651&r=globals PHP 4 support discontinued: https://bugs.php.net/fix.php?id=71651&r=php4 Daylight Savings: https://bugs.php.net/fix.php?id=71651&r=dst IIS Stability: https://bugs.php.net/fix.php?id=71651&r=isapi Install GNU Sed: https://bugs.php.net/fix.php?id=71651&r=gnused Floating point limitations: https://bugs.php.net/fix.php?id=71651&r=float No Zend Extensions: https://bugs.php.net/fix.php?id=71651&r=nozend MySQL Configuration Error: https://bugs.php.net/fix.php?id=71651&r=mysqlcfg