search

redaxo / redaxo4

REDAXO 4
https://redaxo.org
41 stars 26 forks source link

PHP FPM crashed bei heftigen Prozessen (z.b. Metainfo anlegen) #408

Closed kobelobster closed 8 years ago

kobelobster commented 8 years ago

Kurz um gesagt: Wenn ich einen Job starte, der viele Resourcen benoetigt und viele Leute auf'm Server sind, dann krieg ich einen 500er Server Error. Das passiert zum Beispiel, wenn ich ein Meta-Info Feld anlege. Dann kommen 10 Internal Server Errors, bis das irgendwann klappt.

Hier mein Post auf Stackoverflow, also auf Englisch

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
kobelobster commented 8 years ago

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

staabm commented 8 years ago

Für uns interessant ist

[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"

Die ursache des fehlers ist vermutlich ein bug in php selbst. kannst du einen core-dump generieren? https://rtcamp.com/tutorials/php/core-dump-php5-fpm/

Ist deine Anwendung bei diesen Errors dann noch verfügbar, oder werden die FPM Prozess "ordentlich" neugestartet und die Anwendung bleibt verfügbar?

kobelobster commented 8 years ago

Hey staabm. Der Fehler hat irgendwas mit der URL-Generierung zu tun (ist meine Vermutung). Coredump hab ich natürlich vergessen, hier bitte

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 ()
staabm commented 8 years ago

see https://bugs.php.net/bug.php?id=52752 (thx to @bwoebi)

staabm commented 8 years ago

@tzfrs Ist es möglich dass @bwoebi zugangsdaten zum system bekommt um den fehler "live" zu debuggn?

Der Fehler ist unter den php-src devs bekannt, niemand konnte Ihn bisher in einem eigenen System reproduzieren..

kobelobster commented 8 years ago

Also was den PHP-Bug angeht, den haben wir auch bereits gefunden. Allerdings wird das ja nicht das Problem sein, oder? Weil in dem Bug-Report geht es darum, wenn man auf eine Datei per file_put_contents zugreift und dann ein include/require macht, aber wir Redaxo selbst macht ja nur file_put_contents, file_get_contents und file_exists auf ein und die selbe Datei, oder?

staabm commented 8 years ago

Zumindest bekommst du einen ähnlichen stacktrace. mehr kann ich dazu leider nicht sagen.

Es ist übrigens auch möglich via Teamviewer dem php-src dev einen Zugang via ssh zu geben, sodass ihr selbst keine passwörter hergeben müsst.

Ich selbst kann hier leider nur vermitteln. Am besten du kontaktierst mal bwoebi in https://chat.stackoverflow.com/rooms/11/php

von REDAXO seite können wir dir dabei nicht helfen.

kobelobster commented 8 years ago

Hi danke,

ich würde das einmal intern absprechen ob das moeglich ist. Vielen Dank schon einmal