Website lento, servidor ocioso: onde vai o tempo

Porque é que a base de dados é a suspeita do costume

Quando uma página fica lenta, a base de dados é onde o sintoma se torna visível primeiro. As ligações acumulam-se, a lista de processos enche-se de queries no estado sending data, e o slow query log começa a crescer. Tudo isso é real, e nada disso diz para onde foi o tempo. A base de dados está no fim da maioria dos caminhos de pedido. Uma página que a chama duzentas vezes em vez de duas, um worker que mantém uma ligação aberta enquanto espera por um payment gateway, uma cache que é contornada em todos os hits: cada um destes aparece como carga na base de dados, porque a base de dados está a fazer exatamente o que lhe pedem, mais vezes do que lhe deviam pedir.

O mesmo se aplica ao servidor. Uma máquina com load alto é uma máquina a quem estão a dar trabalho. Se o trabalho é necessário é uma pergunta a que o gráfico de load não consegue responder.

Siga um pedido, não o website inteiro

O método é escolher um URL lento e segui-lo pelas camadas, medindo em cada fronteira. Comece de fora, a partir de uma máquina que não está na mesma rede, e deixe o curl reportar para onde vai o tempo antes de chegar o primeiro byte.

$ curl -o /dev/null -s -w 'dns %{time_namelookup}  connect %{time_connect}  tls %{time_appconnect}  ttfb %{time_starttransfer}  total %{time_total}\n' https://www.example.com/slow-page

Se o tempo até ao primeiro byte for a maior parte do total, a espera está do lado do servidor. Se o total for muito maior do que o tempo até ao primeiro byte, a página é pesada ou o caminho entre o visitante e o edge é a história, e o servidor não fez parte da espera.

Na máquina, amostre a CPU enquanto o pedido lento está em curso, não numa hora ociosa mais tarde.

$ mpstat -P ALL 1 5
$ vmstat 1 5

Um servidor que está maioritariamente ocioso durante um pedido lento, sem iowait e sem steal, ilibou-se. O tempo está a ser gasto à espera de algo, não a calcular.

Depois a aplicação. A maioria das frameworks consegue registar, por pedido, o número de queries emitidas, o tempo total gasto nelas, e o tempo gasto em chamadas HTTP de saída. Ative isso para o URL lento. Dois números fecham a discussão: quantas queries uma página emite, e quanto do tempo de relógio foi gasto totalmente fora da aplicação.

Por fim a base de dados, com o slow query log ligado e o limiar suficientemente baixo para apanhar o que importa.

SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 0.2;
SET GLOBAL log_queries_not_using_indexes = ON;

Leia o log na janela do pedido lento. Uma mão-cheia de queries que demoram segundos cada uma é um problema de base de dados. Milhares de queries que demoram um milissegundo cada uma é um problema de aplicação pelo qual a base de dados está a ser culpada.

Os padrões que a medição revela

Com as camadas separadas, a causa costuma tomar uma de poucas formas.

Um endpoint chamado em ciclo. Um front end que volta a pedir o mesmo recurso a cada mudança de estado, ou uma página que emite uma query por linha em vez de uma query por página. A base de dados responde a cada chamada depressa. O número delas é o problema.

Uma chamada síncrona a outra entidade. Um fornecedor de pagamentos, um ERP, uma API de envios, um tag manager, no caminho do pedido atrás de um timeout longo. O servidor fica ocioso durante toda a espera, e a página é tão lenta quanto o terceiro mais lento de que depende.

Uma cache que está a ser derrotada. Headers que proíbem caching em páginas que não mudam, ou nenhuma cache no edge à frente de tráfego anónimo que nunca foi dinâmico.

Pools dimensionados a olho. Pools de workers, ligações e buffers definidos demasiado grandes tantas vezes como demasiado pequenos. Um pool muito maior do que a máquina consegue servir em simultâneo transforma uma fila em thrash.

A exaustão real é a última forma, e quando aparece está normalmente a jusante de uma das três primeiras. A máquina ficar sem alguma coisa é o fim da história, não o princípio.

O que um servidor maior muda

Acrescentar núcleos ou memória encurta a parte do pedido que estava a calcular. Se essa parte já era pequena, a página não fica mais rápida. A espera muda-se com ela. O ciclo continua a repetir-se, o terceiro continua a demorar o seu tempo, a cache continua a ser contornada. A atualização também esconde a medição que teria encontrado a causa, porque o gráfico que estava vermelho está agora âmbar, e o ticket fecha-se.

É por isso que seguimos o rasto antes de orçamentar. Uma plataforma saudável mantém-se aborrecida, e o trabalho é encontrar a camada que detém o tempo, mesmo quando essa camada está acima de tudo o que operamos, e devolver a medição que aponta para a linha.