PHP slowlog empty even though PHP-FPM says it's logging

Question

I have PHP-FPM listening on a Unix domain socket and I've configured the www pool (the only one present) with the following values:

slowlog = /$pool.log.slow
request_slowlog_timeout = 10s

and just for testing I've set max_execution_time in php.ini to 20 seconds. Then I created a test script:

<?php

while(1){
  $i++;
}

?>

Then accessed it via web browser. The script eventually times out due to max_execution_time but the log remains empty:

root@b7e4a919c988:/var/www/html# ll /www.log.slow 
-rw-rw-rw-. 1 www-data root 0 Jan  4 21:31 /www.log.slow

The PHP-FPM log, though seems to indicate that it was expecting to log the slow run:

[04-Jan-2018 21:37:28] WARNING: [pool www] child 9382, script '/var/www/html/test.php' (request: "GET /test.php") executing too slow (13.061999 sec), logging

I've tried a variety of things such as using sleep(10000) or putting the while loop in a function (just in case it couldn't build a stack trace) but nothing seems to get it to print the backtrace to the log. The existence of the logfile itself also seems to indicate FPM is expecting to write slow requests.

At this point I just don't know what else to check.

did you restart the php-fpm service after changing the settings and the script? — EvilTorbalan, Jan 04 '18 at 21:52
@EvilTorbalan Yep. At first I was just doing `kill -SIGUSR2` of the master process but after I started having trouble I switched to just killing all pids and starting `php-fpm7.0` again — Bratchley, Jan 04 '18 at 21:59
You can use service php-fpm restart or systemctl restart php-fpm depending on the linux variant you have. or /etc/init.d/php-fpm restart if its really old ;) — EvilTorbalan, Jan 04 '18 at 22:03
try lowering request_slowlog_timeout to 1s to see if anything gets logged. — EvilTorbalan, Jan 04 '18 at 22:04
@EvilTorbalan This is inside a container so the scripts don't work. I've also tried from a fresh container where `php-fpm` had never been ran before. I've also lowered it down to `1s` and `5s` all with identical behavior. — Bratchley, Jan 04 '18 at 22:18

score 5 · Accepted Answer · answered Jan 09 '18 at 17:42

So after much to-do I finally figured out the problem. The issue is that on Linux, PHP-FPM uses SYS_PTRACE to trace the worker processes (I'm guessing this is how it retrieves the trace data) but docker containers don't allow this capability by default.

Once I ran the docker container with the --cap-add=SYS_PTRACE option and configured the two www.conf settings mention in the OP (slowlog and request_slowlog_timeout).

Contrary to other SO answers I've seen posted, I never had to enable catch_workers_output to get it to work.

The above script generates this output to slowlog:

[09-Jan-2018 17:30:39]  [pool www] pid 9382                
script_filename = /var/www/html/work.php

But to generate a more realistic function trace I wrote this little number:

<?php

function callsSlowFunc(){

  for ($i=0; $i<=10; $i++){
    slowFunc();
  }

}

function slowFunc(){

  for ($j=0; $j <= 50000000; $j++){
    $hey="there";
  }

}

callsSlowFunc();

Which results in this function trace being generated:

[09-Jan-2018 17:40:49]  [pool www] pid 9382
script_filename = /var/www/html/work.php
[0x00007fee53613150] slowFunc() /var/www/html/work.php:6
[0x00007fee536130a0] callsSlowFunc() /var/www/html/work.php:19

PHP slowlog empty even though PHP-FPM says it's logging

1 Answers1