Welcome! Log In Create A New Profile

Advanced

Tracking down a problem with php on FreeBSD

Posted by namikonera 
namikonera
Tracking down a problem with php on FreeBSD
January 23, 2011 04:40PM
Good day!

We are using custom php application on FreeBSD 8.1R amd64. It is
started with php-fpm 5.3.3 from ports as backend and nginx 0.8.54 as
frontend. Several times per day this app is making self unavailable.

Simple php-fpm restart solves the problem, but i need to track it down
to the cause of this situation and ask for your assistance and
instructions on how to debug it. Some facts about this:

- I don't know how to manually reproduce this, but it happens several
times every day
- It happens on FreeBSD 7.x too
- It happens with apache+mod_php instead php-fpm
- It happens with lighthttpd instead nginx
- It happens with both SHED_4BSD and SHED_ULE
- It doesn't happen on php =< 5.2.12
- It happens with and w/o eaccelerator

- `top -mio` shows very high (80000-90000 for VCSW) VCSW/IVCSW values
for php-fpm processes and LA is more than 120
- user seeing http 502 error code in browser
- php-fpm log has many of this lines in time of crash:
Jan 23 17:56:58.176425 [WARNING] [pool world] server reached
max_children setting (100), consider raising it
Jan 23 17:56:59.528873 [WARNING] [pool world] child 686, script
'/usr/local/www/world/public_html/script.php' execution timed out
(10.074251 sec), terminating
Jan 23 17:57:03.221677 [WARNING] [pool world] child 686 exited on
signal 15 (SIGTERM) after 59.424804 seconds from start
Jan 23 17:57:03.222580 [NOTICE] [pool world] child 4407 started
Jan 23 17:57:03.222709 [NOTICE] Finishing ...
Jan 23 17:57:03.260991 [WARNING] [pool site] child 3962, script
'/usr/local/www/site/public_html/script.php' execution timed out
(12.644470 sec), terminating
- nginx log has many of this lines in time of crash:
2011/01/23 17:57:00 [error] 38018#0: *26006023 writev() failed (54:
Connection reset by peer) while sending request to upstream, client:
xx.xx.xx.xx, server: some.server.org, request: "POST /?ctrl=Chat&
a=chatList&__path=chat_list&h=8093b9e1cf448762d5677e21bded97ae&
h1=38ca8b747a46098c3b1a4f39e6658170 HTTP/1.1", upstream:
"fastcgi://127.0.0.1:9002", host: "some.server.org", referrer:
"http://some.server.org/"
2011/01/23 17:57:00 [error] 38016#0: *26029878 kevent() reported
about an closed connection (54: Connection reset by peer) while
reading response header from upstream, client: xx.xx.xx.xx, server:
some.server.org, request: "POST /?ctrl=Location&a=refresh&
__path=refresh&h=276f591df26a65d9a1736f6e1006f4ab&
h1=3c0916c16b1fc2e7015b71e90bbc3d23 HTTP/1.1", upstream:
"fastcgi://127.0.0.1:9002", host: "some.server.org", referrer:
"http://world.mist-game.ru/"
2011/01/23 17:57:02 [crit] 38020#0: *26034390 open() "/tmp/nginx
/client_temp/1/74/0000000741" failed (13: Permission denied) while
sending request to upstream, client: xx.xx.xx.xx, server:
some.server.org, request: "POST /?ctrl=Chat&a=send&__path=chat_send&
h=4a27d8d382ba9b1059412323a451ef84&
h1=b0a53c86e3c744a01356a5030559ed1a HTTP/1.1", upstream:
"fastcgi://127.0.0.1:9002", host: "some.server.org", referrer:
"http://world.mist-game.ru/"
2011/01/23 17:57:02 [alert] 38020#0: *26034390 http request count is
zero while sending to client, client: xx.xx.xx.xx, server:
some.server.org, request: "POST /?ctrl=Chat&a=send&__path=chat_send&
h=4a27d8d382ba9b1059412323a451ef84&
h1=b0a53c86e3c744a01356a5030559ed1a HTTP/1.1", upstream:
"fastcgi://127.0.0.1:9002", host: "some.server.org", referrer:
"http://some.server.org/"
2011/01/23 17:57:03 [error] 38014#0: *25997903 upstream prematurely
closed connection while reading response header from upstream,
client: 109.229.69.186, server: some.server.org, request: "POST
/?ctrl=Chat&a=chatList&__path=chat_list&
h=c8723de73c4f8ebb98f9bf746d75e965&
h1=3ab289760a009b07b73c6d96cc94a509 HTTP/1.1", upstream:
"fastcgi://127.0.0.1:9002", host: "some.server.org", referrer:
"http://some.server.org/"

`top -mio` output in time of crash:
http://pastebin.com/yrCwxnbr

kernel config:
http://pastebin.com/nGA0518A

php port options:
# cat /var/db/ports/php5/options
WITH_CLI=true
WITH_CGI=true
WITH_FPM=true
WITH_APACHE=true
WITHOUT_AP2FILTER=true
WITHOUT_DEBUG=true
WITH_SUHOSIN=true
WITH_MULTIBYTE=true
WITHOUT_IPV6=true
WITH_MAILHEAD=true
WITHOUT_LINKTHR=true

php-fpm pool configuration:
[world]
listen = 127.0.0.1:9002
listen.allowed_clients = 127.0.0.1
listen.owner = www
listen.group = www
listen.mode = 0666
user = www
group = www

pm = dynamic
pm.max_children = 100
pm.start_servers = 20
pm.min_spare_servers = 5
pm.max_spare_servers = 35
pm.max_requests = 5000
pm.status_path = /JWorldStatus

request_terminate_timeout = 10s

Any help is highly appreciated. Thank you all in advance.
Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 153
Record Number of Users: 8 on April 13, 2023
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready