Медленный журнал PHP-FPM возвращает недействительные результаты

Question

Проблема

Я использую PHP-FPM 7.4.30 под Apache 2.4 на RHEL 8 и не могу заставить PHP slowlog работать правильно. Он не возвращает корректную информацию о долго выполняющихся скриптах.

Когда я включаю slowlog – даже с высоким значением, request_slowlog_timeoutнапример, 10 секунд или больше – я вижу, что в журнале появляется много записей, включая скрипты, которые, как я знаю, не являются долгоиграющими. Список выглядит случайным, отображая обратные трассировки для большого количества скриптов и функций внутри них. Очевидной закономерности нет. Я уверен, что возвращаемая информация недействительна. Эти скрипты просто не проходят так долго между запросом и возвратом результата в Apache.

Что должно произойти?

Согласно документации PHP, slowlog должен отмечать только те скрипты, которые выполнялись дольше определенного времени с моментазапросна сервер. Другими словами, он должен измерять время между запросом и завершением работы скрипта. Однако это не то, что происходит, когда я включаю slowlog.

Что, кажется, происходит?

Моя теория заключается в том, что slowlog не измеряет время выполненияиндивидуальные запросыкоторые пришли из Apache, а скорее из того времени, когдадочерний процесс запущен. Поскольку дочерние процессы могут работать довольно долго, они могут показаться длительно работающими скриптами для slowlog. Когда slowlog видит, что дочерний процесс работает более request_slowlog_timeout, он выводит обратную трассировку текущего работающего скрипта (который может быть чем угодно, работающим в этот момент времени).

Мои вопросы

1. Почему PHP-FPM отображает недействительные записи в slowlog? Он не может определить начало запроса?
2. Как настроить Slowlog для записи только того, что нужно: времени выполнения одного запроса?

Я не нашел других отчетов об этой проблеме, но я могу создавать ее каждый раз, когда включаю Slowlog на рабочем сервере, а также на тестовом сервере с одним пользователем.

Большое спасибо за любую информацию или помощь.

Answer 1

Вы случайно не нашли ответ?

У меня та же проблема, и я потратил часы, пытаясь ее решить. Еще более сбивает с толку то, что в журнале ошибок php-fpm будут записи типа

ВНИМАНИЕ: [pool www] дочерний процесс 7559 вышел из-за сигнала 15 (SIGTERM) через 166,818268 секунд после начала

Или

[19-июня-2023 16:24:56] ПРЕДУПРЕЖДЕНИЕ: [pool www] child 7646, скрипт '' (запрос: " ") время выполнения истекло (66.168368 сек), завершение

Однако тот же самый PID нигде не находится в медленном журнале до того, как он достигнет request_terminate_timeout. Логика, казалось бы, диктует, что запрос, который выполнялся в течение 66+ секунд, прежде чем был прекращен, также будет зарегистрирован в медленном журнале через 10 секунд.

Я в тупике