The problem
I’m running PHP-FPM 7.2.11 under Apache 2.4 on CentOS 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 script 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
- Why does PHP-FPM display invalid entries like this in the slowlog? Is it not able to detect the beginning of a request?
- How do I configure the slowlog to record only what’s intended: the run time of a single request?
Thank you very much for any insight or assistance.