Tracking down a problem with php on FreeBSD

[Ruslan Mahmatkhanov]

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://some.server.org/"
   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://some.server.org/"
   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.

-- 
Regards,
Ruslan