1

A low-traffic website on a web server I manage is periodically down with a 503 error until php-fpm is restarted.

The setup is:

  • DigitalOcean droplet
  • CentOS 7.6
  • Apache 2.4 (Event)
  • PHP 5.6.40 (FPM) (Single pool) (OPcache 7.0.6)
  • MariaDB

The Apache error_log shows:

[proxy_fcgi:error] [pid 28424:tid 139973646870272] (70007)The timeout specified has expired: [client 10.16.0.2:47744] AH01075: Error dispatching request to :

An strace -p on each of the php-fpm child processes shows only:

recvfrom(4,

Managing to strace on a thread before it entered this state, I observed:

shutdown(4, SHUT_WR)                    = 0
recvfrom(4, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
recvfrom(4,

An lsof | grep php-fpm | grep WAIT shows:

php-fpm   29271         php-fpm    4u     IPv4            5258526       0t0        TCP mydomain.com:cslistener->mydomain.com:32790 (FIN_WAIT2)
php-fpm   29272         php-fpm    4u     IPv4            5258554       0t0        TCP mydomain.com:cslistener->mydomain.com:32794 (FIN_WAIT2)
php-fpm   29273         php-fpm    4u     IPv4            5273165       0t0        TCP mydomain.com:cslistener->mydomain.com:36460 (FIN_WAIT2)
php-fpm   29274         php-fpm    4u     IPv4            5258499       0t0        TCP mydomain.com:cslistener->mydomain.com:32786 (FIN_WAIT2)
php-fpm   29303         php-fpm    4u     IPv4            5294998       0t0        TCP mydomain.com:cslistener->mydomain.com:42170 (FIN_WAIT2)
php-fpm   29850         php-fpm    4u     IPv4            5309183       0t0        TCP mydomain.com:cslistener->mydomain.com:44630 (FIN_WAIT2)
php-fpm   29851         php-fpm    4u     IPv4            5279040       0t0        TCP mydomain.com:cslistener->mydomain.com:37966 (FIN_WAIT2)
php-fpm   29857         php-fpm    4u     IPv4            5295075       0t0        TCP mydomain.com:cslistener->mydomain.com:42198 (FIN_WAIT2)
php-fpm   30472         php-fpm    4u     IPv4            5295345       0t0        TCP mydomain.com:cslistener->mydomain.com:42216 (FIN_WAIT2)
php-fpm   32086         php-fpm    4u     IPv4            5295802       0t0        TCP mydomain.com:cslistener->mydomain.com:42334 (FIN_WAIT2)

If I kill one of the child processes, a new one is spawned and the website continues to function, until that process also ends up in the same state.

Restarting php-fpm always resolves the issue. Restarting Apache or MariaDB makes no difference.

An strace -p of the main php-fpm process shows this continually:

socket(AF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 9
sendmsg(9, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"READY=1\nSTATUS=Processes active:"..., 87}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 87
close(9)                                = 0
epoll_wait(8, [], 1, 656)               = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0
epoll_wait(8, [], 1, 1000)              = 0
getsockopt(7, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\201\0\0\0\200\0\0\0"..., [104]) = 0

Apache config for PHP handling:

<FilesMatch "\.php$">
    <If "-f %{REQUEST_FILENAME}">
        SetHandler "proxy:fcgi://localhost:9000"
    </If>
</FilesMatch>

The php-fpm pool is configured as follows:

[www]
user = php-fpm
group = php-fpm
listen = 127.0.0.1:9000
listen.allowed_clients = 127.0.0.1
pm = dynamic
pm.max_children = 10
pm.start_servers = 4
pm.min_spare_servers = 4
pm.max_spare_servers = 6
pm.process_idle_timeout = 10s
pm.max_requests = 500
slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 10
catch_workers_output = yes
php_admin_value[error_log] = /var/log/php-fpm/www-error.log
php_admin_flag[log_errors] = on
php_value[session.save_handler] = files
php_value[session.save_path]    = /var/lib/php-fpm/session
php_value[soap.wsdl_cache_dir]  = /var/lib/php-fpm/wsdlcache

The slow log is empty; the only output from each of the workers is:

WARNING: [pool www] child 2840 said into stderr: "ERROR: Unable to set php_value 'soap.wsdl_cache_dir'"

That, I'm guessing is only a warning because the SOAP extension isn't installed.

Edit:

  • Setting to static mode and removing the max requests line makes no difference.

  • According to the PHP-FPM status page, the "stuck" threads are in "Finishing" state. They consume 0% CPU at this point.

  • The PHP script that I believe is primarily affected/responsible serves cached images; max size < 1MB

  • Disabling OPCache makes no difference.

  • This is possibly the most significant lead; the request to the script which causes the issue has a response time of 60 seconds only when YandexBot hits it and it's after this point when the thread enters the hung state (the response time in seconds is appended to the log line):

[28/Apr/2019:08:44:46 +0100] "GET /imgsizr?i=123.jpg&t=large HTTP/1.1" 200 192167 "-" "Mozilla/5.0 (compatible; YandexBot/3.0; +http://yandex.com/bots)" 60

Edit 2: Changing to a UDS (Unix Domain Socket) cures the problem in as much as the finishing state still happens, but eventually transitions to Idle.

  • So why does this one exhibit the behavior? What is different? Perhaps remove the lines causing the warnings if that is the only difference? Otherwise maybe look at these parameters... <Proxy fcgi://foo/> ProxySet timeout=300 connectiontimeout=10 disablereuse=on </Proxy> – ficuscr Apr 26 at 16:43
  • Nothing useful in the php-fpm error.log? – ficuscr Apr 26 at 16:56
  • I do not know why this droplet exhibits this behaviour. It is simply LAMP setup the same as other web servers hosting different websites; so essentially the only difference is the website itself. The PHP error log has nothing of any help. I can certainly try defining a proxy in the Apache config. I'm not sure which parameters (disablereuse) etc should be set on a pool not using unix sockets. Using a unix socket is the other thing I could try, although again, doesn't explain what's going on. – jamieburchell Apr 26 at 20:24
  • It seems that by not defining the worker, the default proxy will be used that doesn't have connection reuse or keep alive active anyway: "The two default workers have a fixed configuration and will be used if no other worker matches the request. They do not use HTTP Keep-Alive or connection reuse." – jamieburchell Apr 26 at 20:58
  • PHP 5.6 is out of support. It might not be possible to solve this problem. Consider updating to a currently supported PHP version. – Michael Hampton Apr 26 at 20:58

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.