PHP7.3-FPM with Apache: Unknown script request execution timed out

Question

I configured Apache 2.4 MPM Event with PHP7.3-FPM on a pretty busy web server as follows:

Timeout 90

<Proxy "unix:/run/php/php7.3-fpm.sock|fcgi://php-fpm">
    ProxySet disablereuse=on timeout=90
</Proxy>

<FilesMatch ".+\.php$">
        SetHandler proxy:fcgi://php-fpm
</FilesMatch>

The PHP config in /etc/php/7.3/fpm/php.ini is set to

max_execution_time=60

The PHP-FPM is configured in /etc/php/7.3/fpm/pool.d/www.conf to

request_terminate_timeout=90

The read timeouts are configured in /etc/apache2/mods-enabled/reqtimeout.conf like this:

RequestReadTimeout header=20-120,minrate=50
RequestReadTimeout body=60-120,minrate=50

In FPM log now I can see every minute 1-2 workers for unknown requests which are killed after 90+ seconds.

[16-May-2019 09:25:32] WARNING: [pool www] child 105567, script '' (request: " ") execution timed out (113.002653 sec), terminating
[16-May-2019 09:25:32] WARNING: [pool www] child 105567 exited on signal 15 (SIGTERM) after 4050.136381 seconds from start
[16-May-2019 09:25:32] NOTICE: [pool www] child 110414 started

If I don't set request_terminate_timeout to kill these workers they stay longer (~5 minutes) in state "Reading headers" and block the PHP-FPM pool.

The threads in Apache MPM seem not to get blocked anyway. Nothing is hitting the max workers values.

How can I see which script/request these PHP workers belong to? Why these scripts are running even after max_execution_time of 60 seconds has expired? How can I avoid blocking the PHP pool by such requests?

I suspect there could be sometimes incomplete HTTPS requests which are starting the PHP worker somehow. Is there a way to avoid starting a PHP worker for these?

Answer 1

As @constantin-galbenu mentions in their comment, the Apache <Proxy> directive's enablereuse=on does not play well with PHP-FPM's prefork multi-processing model as described in https://bugs.php.net/bug.php?id=69890

[2019-05-02 10:03 UTC] mp at webfactory dot de

For the record, the Apache manual at https://httpd.apache.org/docs/current/mod/mod_proxy_fcgi.html#examples says:

Enable connection reuse to a FCGI backend like PHP-FPM

Please keep in mind that PHP-FPM (at the time of writing, February 2018) uses a prefork model, namely each of its worker processes can handle one connection at the time. By default mod_proxy (configured with enablereuse=on) allows a connection pool of ThreadsPerChild connections to the backend for each httpd process when using a threaded mpm (like worker or event), so the following use cases should be taken into account:

Under HTTP/1.1 load it will likely cause the creation of up to MaxRequestWorkers connections to the FCGI backend.

Under HTTP/2 load, due to how mod_http2 is implemented, there are additional h2 worker threads that may force the creation of other backend connections. The overall count of connections in the pools may raise to more than MaxRequestWorkers.

The maximum number of PHP-FPM worker processes needs to be configured wisely, since there is the chance that they will all end up "busy" handling idle persistent connections, without any room for new ones to be established, and the end user experience will be a pile of HTTP request timeouts.

My interpretation of this is that with enablereuse=on, every Apache MPM worker process/thread can have an open connection to PHP-FPM. In the PHP-FPM status page, those will show up as "Reading headers..." (or similar). These processes seem to be active (waiting) for PHP-FPM and so they are not terminated.

My own issue was with webservers using Apache's event Multi-Processing Module (MPM) passing PHP execution to PHP-FPM using the example configuration from Apache's mod_proxy_fcgi documentation:

<FilesMatch "\.php$">
    # Note: The only part that varies is /path/to/app.sock
    SetHandler  "proxy:unix:/path/to/app.sock|fcgi://localhost/"
</FilesMatch>

# Define a matching worker.
# The part that is matched to the SetHandler is the part that
# follows the pipe. If you need to distinguish, "localhost; can
# be anything unique.
<Proxy "fcgi://localhost/" enablereuse=on max=10>
</Proxy>

With this configuration I was seeing unexplained 503 proxy errors from Apache with the application periodically unresponsive until PHP-FPM was restarted. After adding request_terminate_timeout = 5m to my /etc/php-fpm.d/www.conf to force-kill long-running PHP-FPM requests my application became a bit more stable and I began seeing errors like the following in my /var/log/php-fpm/error.log and less frequent failures that would last for a few minutes before recovering without intervention:

[04-Jan-2023 15:19:26] WARNING: [pool www] child 349975, script '' (request: " ") execution timed out (362.004673 sec), terminating
[04-Jan-2023 15:19:26] WARNING: [pool www] child 349975 exited on signal 15 (SIGTERM) after 1200.012433 seconds from start

After removing the enablereuse=on flag from my Apache configuration I no longer see the above timeout errors in my /var/log/php-fpm/error.log. The new configuration is:

<FilesMatch "\.php$">
  <If "-f %{REQUEST_FILENAME}">
    # Pick one of the following approaches
    #
    # Use the standard TCP socket
    #SetHandler "proxy:fcgi://localhost:9000"
    # If your version of httpd is 2.4.9 or newer (or has the back-ported feature), you can use the unix domain socket
    #SetHandler "proxy:unix:/path/to/app.sock|fcgi://localhost/"
    SetHandler "proxy:unix:/run/php-fpm/www.sock|fcgi://localhost/"
  </If>
</FilesMatch>

# Defining a worker will improve performance
# And in this case, re-use the worker (dependent on support from the fcgi application)
# If you have enough idle workers, this would only improve the performance marginally
#
# enablereuse=on is only available in Apache >= 2.4.11
<Proxy "fcgi://localhost/" max=10>
</Proxy>