PHP-FPM slow log returning invalid results

The problem

I’m running PHP-FPM 7.4.30 under Apache 2.4 on RHEL 8, and I’m not able to get PHP’s slowlog to work properly. It won’t return valid information about long-running scripts.

When I enable the slowlog – even with a high value for request_slowlog_timeout like 10 seconds or more – I see many entries appear in the log, including scripts that I know are not long-running. The list appears random, displaying backtraces for a large variety of scripts and functions inside them. There’s no obvious pattern. I’m sure that the information returned is not valid. These scripts simply do not take that long between request and returning a result to Apache.

What should happen

According to the PHP documentation, the slowlog should flag only those scripts that ran for more than a certain time since the request to the server was made. In other words, it should measure the time between the request and when the script finished running. However, this is not what happens when I enable the slowlog.

What seems to be happening

My theory is that the slowlog is not measuring the runtime of individual requests that come from Apache, but rather of the time that a child process has been running. Since child processes can run for a rather long time, they may appear to be long-running scripts for the slowlog. When the slowlog sees that a child process has run for more than request_slowlog_timeout, it outputs a backtrace of the currently running script (which could be anything running at that moment in time).

My questions

1. Why does PHP-FPM display invalid entries like this in the slowlog? Is it not able to detect the beginning of a request?
2. How do I configure the slowlog to record only what’s intended: the run time of a single request?

I haven't found any other reports of this issue, but I'm able to produce it every time I enable the slowlog on a production server as well as on a test server with just one user.

Thank you very much for any insight or assistance.

Did you by chance find an answer?

I have the same issue and have spent hours trying to figure it out. It's even more confounding that the php-fpm error log will have entries like

WARNING: [pool www] child 7559 exited on signal 15 (SIGTERM) after 166.818268 seconds from start

Or

[19-Jun-2023 16:24:56] WARNING: [pool www] child 7646, script '' (request: " ") execution timed out (66.168368 sec), terminating

However, that same PID is nowhere to be found in the slow log before it reaches request_terminate_timeout. Logic would seem to dictate a request that ran for 66+ seconds before getting terminated would also be logged to the slow log after 10s.

I am stumped