2

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 4 '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 4 '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 4 '18 at 22:03
  • try lowering request_slowlog_timeout to 1s to see if anything gets logged. – EvilTorbalan Jan 4 '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 4 '18 at 22:18
3

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

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.