У меня есть PHP-FPM, прослушивающий сокет домена Unix, и я настроил www бассейн (единственный подарок) со следующими значениями:
slowlog = /$pool.log.slow
request_slowlog_timeout = 10s
и просто для тестирования я установил max_execution_time в php.ini до 20 секунд. Затем я создал тестовый скрипт:
<?php
while(1){
$i++;
}
?>
Затем открыли его через веб-браузер. Время ожидания сценария истекает из-за max_execution_time но журнал остается пустым:
root@b7e4a919c988:/var/www/html# ll /www.log.slow
-rw-rw-rw-. 1 www-data root 0 Jan 4 21:31 /www.log.slow
Журнал PHP-FPM, хотя, похоже, указывает на то, что он ожидал регистрации медленного запуска:
[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
Я пробовал разные вещи, например, использовал sleep(10000) или поставить while цикл в функции (на тот случай, если он не смог построить трассировку стека), но, похоже, ничто не заставляет его печатать обратную трассировку в журнал. Само существование файла журнала также указывает на то, что FPM ожидает записи медленных запросов.
На данный момент я просто не знаю, что еще проверить.
Итак, после долгих дел я наконец понял проблему. Проблема в том, что в Linux PHP-FPM использует SYS_PTRACE для отслеживания рабочих процессов (я предполагаю, что именно так он получает данные трассировки), но docker по умолчанию контейнеры не позволяют использовать эту возможность.
Как только я запустил контейнер докеров с --cap-add=SYS_PTRACE вариант и настроил два www.conf настройки, упомянутые в ОП (slowlog и request_slowlog_timeout).
В отличие от других ответов SO, которые я видел опубликованными, мне никогда не приходилось включать catch_workers_output чтобы заставить его работать.
Приведенный выше сценарий генерирует этот вывод в slowlog:
[09-Jan-2018 17:30:39] [pool www] pid 9382
script_filename = /var/www/html/work.php
Но чтобы создать более реалистичную трассировку функции, я написал это маленькое число:
<?php
function callsSlowFunc(){
for ($i=0; $i<=10; $i++){
slowFunc();
}
}
function slowFunc(){
for ($j=0; $j <= 50000000; $j++){
$hey="there";
}
}
callsSlowFunc();
В результате создается эта трассировка функции:
[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