Agrupar os slow logs do PHP-FPM para descobrir o que o seu site espera

«O site está lento» não é algo que alguém consiga corrigir. «Quatro em cada dez pedidos lentos estão à espera de uma chamada a uma API externa» é. O PHP-FPM consegue dizer a segunda frase de graça, através de um log que a maioria dos servidores tem desligado. Eis como o ligar, como o ler e como o agrupar para que a resposta apareça por si.

O problema: lento, mas onde?

Quando as páginas PHP estão lentas, a maioria das investigações começa de fora (ferramentas de medição de tempo de página) ou pela base de dados (slow query log). Ambas são úteis, e ambas falham a causa mais comum nos sites modernos: o PHP à espera de algo que não é CPU nem a base de dados local. Um gateway de pagamento. Uma API de stock ou de ERP. Uma verificação de licença. Um bloqueio de sessão mantido por outro pedido do mesmo visitante. Essas esperas não aparecem como CPU, por isso o servidor parece inativo enquanto os visitantes olham para um spinner.

O slow log do PHP-FPM apanha-as todas, porque não lhe interessa porque é que um pedido está lento. Limita-se a tirar um instantâneo do que o pedido está a fazer.

Ligue-o

Na configuração do pool (por exemplo /etc/php-fpm.d/www.conf):

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 3s
request_terminate_timeout = 60s

Quando um pedido está a correr há mais tempo do que o request_slowlog_timeout, o master do FPM tira um backtrace do worker e escreve-o no slow log. O pedido continua. Nada é terminado. O request_terminate_timeout é uma rede de segurança separada que termina mesmo os pedidos descontrolados, e vale a pena defini-lo já que está aqui.

Escolha um limiar ligeiramente acima do que parece «normal» para as suas páginas sem cache. Demasiado baixo, e regista pedidos saudáveis. Demasiado alto, e só vê os desastres. Faça reload ao FPM e deixe-o recolher durante um período de tráfego.

Leia uma entrada

Uma entrada do slow log tem este aspeto:

[22-Oct-2026 10:14:07]  [pool www] pid 41822
script_filename = /var/www/shop/index.php
[0x00007f1c2a614f20] curl_exec() /var/www/shop/modules/erpsync/Client.php:188
[0x00007f1c2a614e10] request() /var/www/shop/modules/erpsync/Client.php:97
[0x00007f1c2a614d00] getStock() /var/www/shop/modules/erpsync/Stock.php:42
[0x00007f1c2a614bf0] hookDisplayProduct() /var/www/shop/classes/Hook.php:1017
...
[0x00007f1c2a6140a0] dispatch() /var/www/shop/index.php:28

O frame de topo, o que está imediatamente abaixo de script_filename, é aquilo em que o pedido estava bloqueado no momento do instantâneo. Por baixo está o caminho que o levou até lá. Neste exemplo, uma página de produto está à espera de curl_exec(), chamado por um módulo de sincronização de stock, durante a apresentação do produto.

Uma entrada é uma anedota. Um dia inteiro delas é um perfil.

Agrupe pelo frame que bloqueia

Agrupe cada entrada pelo seu frame de topo e conte:

awk '/^script_filename/ { w = 1; next }
     w && /^\[0x/ {
       fn = $2
       match($0, /[^ ]+:[0-9]+$/)
       print fn " @ " substr($0, RSTART, RLENGTH)
       w = 0
     }' /var/log/php-fpm/www-slow.log \
  | sort | uniq -c | sort -rn | head -25

O resultado é uma lista ordenada do que os pedidos lentos estavam realmente a fazer. Numa loja online lenta típica pode ter este aspeto:

 812 curl_exec() @ .../modules/erpsync/Client.php:188
 497 execute() @ .../classes/db/DbPDO.php:132
 251 session_start() @ .../config/bootstrap.php:61
  88 file_get_contents() @ .../themes/shop/fonts.php:12

Depois agrupe de uma segunda forma, pelo primeiro frame dentro de um diretório de plugin, módulo ou tema. Isso transforma a lista de «que função» em «código de quem», que é a pergunta que os programadores vão fazer.

O que significam os frames mais comuns

• curl_exec(), file_get_contents() sobre um URL, fsockopen(): uma chamada externa feita de forma síncrona durante a geração da página. Veja o timeout que usa. Um timeout longo contra um terceiro lento prende um worker durante esse tempo todo. A correção é um timeout curto, guardar a resposta em cache, ou tirar a chamada do pedido da página.
• execute(), query(), mysqli_query(): uma espera pela base de dados. Leve o ficheiro e a linha ao slow query log e faça EXPLAIN à query que corre ali. Se o buffer pool está a responder a partir da memória e a query continua a demorar segundos, o problema é a query ou os seus índices, não o hardware.
• session_start(): quase sempre bloqueio de sessão. Os handlers de sessão em ficheiros, e alguns em base de dados, bloqueiam a sessão durante todo o pedido, por isso um visitante cujo browser dispara vários pedidos ao mesmo tempo vê-os ficar em fila uns atrás dos outros. Feche a sessão cedo com session_write_close() assim que o código tiver o que precisa, ou use um handler não bloqueante.
• sleep(), usleep(), ciclos de repetição: o código de alguém está a esperar de propósito. Normalmente uma repetição contra um serviço externo que está a ter um dia mau.
• Funções PHP puras bem dentro de um template ou de um ciclo: trabalho genuíno de CPU. Mais raro do que a maioria espera, e a única categoria em que hardware mais rápido ajuda diretamente.

Pese-o, e depois confirme o pool

O slow log conta pedidos acima do limiar. Não diz quanto tempo total custa cada categoria. Combine-o com o access log do seu servidor web, registando $request_time e $upstream_response_time no nginx, para pesar os pedidos lentos por URL e por duração. Uma categoria com menos entradas mas pedidos muito mais longos pode pesar mais.

Depois verifique se os pedidos lentos estão também a esgotar o pool:

grep -c 'reached pm.max_children' /var/log/php-fpm/error.log
curl -s 'http://localhost/fpm-status?full' | head -20

Se os workers se esgotam, os visitantes ficam em fila mesmo para páginas que por si só são rápidas. Aumentar pm.max_children trata o sintoma. Encurtar a chamada externa lenta trata a causa.

Uma palavra sobre o overhead

Tirar um backtrace significa que o master do FPM se liga por breves instantes ao worker. Com um limiar sensato o overhead é negligenciável, porque só acontece a pedidos que já estão lentos. Não defina o limiar numa fração de segundo num site movimentado e o deixe lá ficar. Recolha, analise e depois volte a subi-lo para um nível de monitorização.

A sua lista de verificação

• slowlog, request_slowlog_timeout e request_terminate_timeout definidos em todos os pools.
• Um dia de slow log agrupado pelo frame que bloqueia, e depois por plugin ou módulo.
• Chamadas externas identificadas e os seus timeouts lidos.
• Frames de base de dados seguidos até às queries dessas linhas, com EXPLAIN.
• Entradas session_start() verificadas quanto a bloqueio de sessão.
• Pedidos lentos pesados por duração a partir do access log, e esgotamento do pool confirmado ou excluído.

Quando um slow log aponta para um sítio difícil de seguir, teremos todo o gosto em ajudar a lê-lo.

Fale com um engenheiro

Related

Relacionados: Auditorias de desempenho de aplicações web · Upgrades de PHP e patching de segurança em toda a frota · Camadas web de alta disponibilidade, N+1 em cada nível