Servidor ou aplicação: como medir o bottleneck

Tempo até ao primeiro byte em cada salto

As teorias sobre um website lento formam-se facilmente e fecham-se com dificuldade. Três medições fecham-nas. Meça o tempo até ao primeiro byte através do edge público, de novo diretamente contra o origin com o edge contornado, e de novo no host da aplicação contra localhost. A diferença entre duas leituras adjacentes é o custo dessa camada.

# through the edge
curl -s -o /dev/null -w 'dns=%{time_namelookup} tls=%{time_appconnect} ttfb=%{time_starttransfer}\n' https://site.example/

# direct to the origin, edge bypassed
curl -s -o /dev/null -w 'ttfb=%{time_starttransfer}\n' --resolve site.example:443:ORIGIN_IP https://site.example/

# on the host, nothing in front of the application
curl -s -o /dev/null -w 'ttfb=%{time_starttransfer}\n' http://127.0.0.1/

O que resta em localhost é a aplicação e os serviços que ela chama. A camada com o maior intervalo é para onde vai o resto do trabalho.

Margem enquanto dói

Leia os contadores durante o período lento, não depois.

vmstat 1 5        # r (run queue), wa (I/O wait), st (steal), id (idle)
iostat -x 1 5     # await and aqu-sz per device
free -m           # the available column, not used

Uma run queue longa com idle baixo é uma máquina limitada pela CPU. I/O wait alto com await alto no dispositivo é storage. Steal é um vizinho num hypervisor partilhado a levar ciclos que o guest queria. CPU idle, memória disponível e dispositivos com await baixo por baixo de um website lento significam que a máquina está à espera de algo que não lhe pertence: uma chamada externa, um lock, uma query lenta por razões que não o hardware. Acrescentar hardware nesse ponto produz uma máquina mais ociosa que continua lenta.

Há uma terceira categoria entre as duas, e é comum: o pool. A página de status do PHP-FPM mostra uma listen queue. Uma fila de pedidos à espera com a CPU idle significa que todos os workers estão ocupados, normalmente bloqueados na mesma chamada lenta, e o website está lento por causa de um teto de configuração e não de um teto de recursos. A mesma forma aparece como um connection pool de base de dados saturado ou uma fila de backend cheia no HAProxy. A máquina está inocente e o código ainda não foi condenado. O tamanho do pool e a chamada pela qual espera são as duas leituras seguintes.

Leia o tráfego antes do código

O access log diz que tipo de problema é este. Encontre primeiro o log por vhost. O log por omissão pode conter uma pequena fração do tráfego real, e uma contagem sobre o ficheiro errado dá uma resposta errada com toda a confiança.

tail -n 100000 access.log | awk -F'"' '{print $2}' | sort | uniq -c | sort -rn | head

Alguns URL repetidos milhares de vezes é o website a chamar-se a si próprio, e a solução é uma cache à frente desses URL. Pedidos a avançar pela ordem do sitemap são um crawler, e a solução é um rate limit. Uma subida ampla e uniforme em muitos URL é procura, e a solução é capacidade.

Condense o slow log e o query log

Um slow log é uma pilha de stack traces até ser agrupado. Ative o slow log do PHP-FPM com um limiar que apanhe os pedidos de que os utilizadores se queixam, depois agrupe cada trace pelo frame em que ficou bloqueado, a folha, e conte. A lista ordenada é curta e no topo está normalmente uma chamada externa ou uma query.

Do lado da base de dados, ordene por digest, não por plano. A parametrização inconsistente divide uma query lógica em muitos planos que parecem inofensivos cada um por si. Somado por digest, o verdadeiro dono do tempo da base de dados volta a juntar-se numa única linha.

-- MySQL and Percona: by statement digest
SELECT digest_text, count_star, sum_timer_wait
FROM performance_schema.events_statements_summary_by_digest
ORDER BY sum_timer_wait DESC
LIMIT 10;

-- SQL Server: by query hash
SELECT query_hash, COUNT(*) AS plans, SUM(total_worker_time) AS cpu
FROM sys.dm_exec_query_stats
GROUP BY query_hash
ORDER BY cpu DESC;

Antes de escrever qualquer índice, verifique a contagem real de linhas e os índices que já existem. Um índice numa tabela que não precisa dele é um caminho de escrita mais lento.

Leia a fonte primária, não uma história plausível

Cada linha substitui uma teoria por uma leitura. A última conta num sistema em enforcing: o audit log responde à pergunta sem alterar a postura de segurança para a fazer.

Prove, depois verifique com a mesma medição

A correlação dá um suspeito. Uma perturbação pequena e reversível condena-o: pare as queries suspeitas durante alguns segundos e observe se o load volta a encher. Se encher de imediato, o tráfego em produção é o fator e a solução pertence ao edge, à frente dos pedidos que nem sequer deviam chegar à base de dados. Até a causa ser conhecida, o sistema é só de leitura. Quando a correção entra, é verificada com a medição que encontrou o problema: se o tempo até ao primeiro byte por salto o localizou, o tempo até ao primeiro byte por salto confirma que desapareceu.

O que corrigimos e o que devolvemos

Não alteramos o seu código. Nomeamos a linha, mostramos a medição que aponta para ela e mantemos o website no ar enquanto a corrige.