O problema
Estou executando o PHP-FPM 7.4.30 no Apache 2.4 no RHEL 8 e não consigo fazer o slowlog do PHP funcionar corretamente. Não retornará informações válidas sobre scripts de longa execução.
Quando habilito o slowlog – mesmo com um valor alto por request_slowlog_timeoutcerca de 10 segundos ou mais – vejo muitas entradas aparecerem no log, incluindo scripts que sei que não são de longa duração. A lista parece aleatória, exibindo backtraces para uma grande variedade de scripts e funções dentro deles. Não há um padrão óbvio. Tenho certeza de que as informações retornadas não são válidas. Esses scripts simplesmente não demoram muito entre a solicitação e o retorno de um resultado ao Apache.
O que deveria acontecer
De acordo com a documentação do PHP, o slowlog deve sinalizar apenas os scripts que foram executados por mais de um determinado tempo desde osolicitarpara o servidor foi feito. Em outras palavras, deve medir o tempo entre a solicitação e o término da execução do script. Porém, não é isso que acontece quando habilito o slowlog.
O que parece estar acontecendo
Minha teoria é que o slowlog não mede o tempo de execução dosolicitações individuaisque vêm do Apache, mas sim da época em que umprocesso filho está em execução. Como os processos filhos podem ser executados por um longo período de tempo, eles podem parecer scripts de longa execução para o slowlog. Quando o slowlog vê que um processo filho foi executado por mais de request_slowlog_timeout, ele gera um backtrace do script atualmente em execução (que pode ser qualquer coisa em execução naquele momento).
Minhas perguntas
- Por que o PHP-FPM exibe entradas inválidas como esta no slowlog? Não consegue detectar o início de uma solicitação?
- Como configuro o slowlog para registrar apenas o pretendido: o tempo de execução de uma única solicitação?
Não encontrei nenhum outro relatório sobre esse problema, mas consigo produzi-lo sempre que habilito o slowlog em um servidor de produção e também em um servidor de teste com apenas um usuário.
Muito obrigado por qualquer informação ou assistência.
Responder1
Você por acaso encontrou uma resposta?
Eu tenho o mesmo problema e passei horas tentando descobrir. É ainda mais confuso que o log de erros do php-fpm tenha entradas como
AVISO: [pool www] filho 7559 saiu no sinal 15 (SIGTERM) após 166,818268 segundos do início
Ou
[19-Jun-2023 16:24:56] AVISO: [pool www] filho 7646, script '' (solicitação: "") a execução expirou (66,168368 segundos), encerrando
No entanto, esse mesmo PID não pode ser encontrado em nenhum lugar no log lento antes de atingir request_terminate_timeout. A lógica parece ditar que uma solicitação executada por mais de 66 segundos antes de ser encerrada também seria registrada no log lento após 10s.
Estou perplexo