Chegou um alerta dizendo que o banco tinha caído. O banco nunca caiu

Abri o Slack de manhã e havia quatro alertas CRITICAL empilhados.

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

A última linha é a mais assustadora. Quer dizer que o banco morreu. Olhando os quatro juntos numa tela, desenha-se uma história só. O banco sofreu, as queries se acumularam, as requisições estouraram o timeout e no fim até o health check falhou. É uma história plausível.

Por isso abri primeiro as métricas do banco. E a história caiu já na primeira tela.

O banco ficou ocioso por 21 horas seguidas

Puxei as métricas do RDS de uma janela de 21 horas, incluindo o horário do incidente, em intervalos de 5 minutos. 252 pontos de dados.

Métrica	Mínimo	Máximo
CPU	4,6%	19,7%
Conexões	53	73
Saldo de créditos de CPU	576	576
Latência de leitura	0s	0,01s
Latência de escrita	0,01s	0,08s

A CPU nunca passou de 20%, e o saldo de créditos tem mínimo igual ao máximo. Ou seja, não gastou nenhum. A latência de escrita chegou no máximo a 80 milissegundos. Conferi também o RDS Proxy. Latência de empréstimo de conexão no máximo 26 milissegundos, conexões de backend no máximo 36. Em lugar nenhum havia um número capaz de explicar queries de 8 ou 10 segundos.

O banco não tinha morrido. Nem sequer estava ocupado.

Uma requisição atravessa o Atlântico vinte e cinco vezes

Então de onde vinham as queries de 8 segundos? Basta olhar a arquitetura para achar a resposta.

Nosso serviço roda em duas regiões, us-east e eu-west. Existe um único primary, em us-east; as leituras do app em eu-west são atendidas pela réplica local, mas todas as escritas atravessam o Atlântico e vão, passando pelo RDS Proxy, para o primary em us-east.

O problema era o número de escritas. Segui pelo código uma requisição de salvar um registro de prática (POST /customer/practice/attempts) e fui contando. 1 upsert de asset, 3 leituras de agregados pré-computados, 4 na transação da tentativa de estudo, 1 re-consulta do runner, 2 a 3 atualizações de progresso, cerca de 6 na transação de streak, 2 na transação de estatísticas, 2 a 3 atualizações de estado de revisão. Cerca de vinte e cinco, distribuídas por três blocos de transações interativas independentes.

Esse número estava lá, cravado no log.

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 queries, 11,7 segundos. E essa requisição nem falhou. Aguentou os 11,7 segundos e terminou com 201.

Aqui preciso ser honesto sobre uma coisa. Eu não medi quantos milissegundos custa cada uma dessas idas e voltas. Um comentário no código dizia que o RTT entre regiões era de 220 milissegundos, outro dizia 80 a 100 milissegundos por frase. Sem verificar qual dos dois estava certo, escrevi no corpo da issue a conta "25 x 220ms = 5,5 segundos". Olhando agora, isso não é medição, é citação. A afirmação exata é esta: contei o número de idas e voltas (25) e não medi o custo de cada ida e volta. Ainda assim, a conclusão não muda. Vinte e cinco travessias do Atlântico acumulam custo na casa dos segundos.

No pico da manhã na Europa (06:00 às 06:10 UTC), 57 escritas no primary passaram dos 3 segundos. LearningAttempt.create 8.989ms, UserActiveDate.upsert 9.070ms, LearningAttempt.findUnique 10.561ms. As requisições se atropelavam e a latência das idas e voltas ia se somando.

Dois dos alertas nasceram nessa brecha.

Alertas 1 e 2: uma transação de 5 segundos não aguentou 9,3 segundos

O código que atualiza o streak era assim.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... seis queries que atravessam a regiao ...
});

Não há objeto de opções. Logo, vale o timeout padrão de transação interativa do Prisma: 5.000 milissegundos. Normalmente não dá problema. Desde que não se atravesse uma região.

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9.326 milissegundos. E isso vira P2028, e a requisição vira 504 no gateway.

Esse código era o único desprotegido de toda a nossa base. Os outros caminhos de transação passam pelo utilitário withTxRetry, que sobe o timeout para 8 segundos e trata o P2028 como caso de retry. Só a atualização de streak ficou fora desse guarda-chuva, usando o padrão de 5 segundos.

Alerta 4: o health check passou pelo gargalo que ele mesmo vigiava

O mais assustador, "serviço DATABASE fora do ar", era na verdade o mais ridículo.

O código do health check era bem escrito. Dispara um SELECT 1 com timeout de 2 segundos; se falha, espera 500 milissegundos e tenta mais uma vez; se falha de novo, dispara o alerta CRITICAL. Tinha até um pool de conexões dedicado (máximo de 2) para não se misturar com o pool do Prisma do app. O objetivo do design era manter o health check vivo mesmo com o pool do app exaurido.

Só que o caminho por onde essa sonda chega ao banco não estava isolado.

// health.service.ts:139
// Se DIRECT_DATABASE_URL existir, usa; senao, cai para DATABASE_URL

O DIRECT_DATABASE_URL não estava configurado. O fallback entrou em ação, e o DATABASE_URL aponta justamente para o RDS Proxy onde as escritas do app estavam concentradas. Ou seja, o SELECT 1 disparado pela sonda de saúde em eu-west tinha que atravessar o Atlântico, passar pelo proxy que estava travando naquele momento e chegar até o primary em us-east, ida e volta. Em menos de 2 segundos.

O código sabia disso. Quando o fallback é acionado, ele deixa este aviso.

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

Essa linha estava lá, no log, exatamente assim. Só que ninguém a leu.

A evidência decisiva é que as duas regiões falharam juntas, no mesmo horário. 12:02:17, timeout no health check da task de us-east. 12:02:18, timeout também na task de eu-west. Se fosse um problema regional, só um lado deveria morrer. Os dois morrerem juntos significa que a causa está no que eles compartilham: o caminho do proxy.

O que veio depois já era previsível. Como o health check falhou duas vezes, o /public/health respondeu 503, o orquestrador considerou a task problemática e a substituiu. Quatro minutos depois, subiu uma task nova. Assim que bootou, a task nova bateu no mesmo timeout de health check. Trocar a task não estreita o Atlântico.

"Serviço DATABASE fora do ar" não era sintoma da falha. Era o instrumento de vigilância caminhando pela estrada congestionada de quem ele vigiava e depois relatando que estava sofrendo.

O 500 do admin era outro caso

Aqui bate a tentação de amarrar os quatro alertas num só. No começo, eu também tentei organizar assim. Mas o 500 do admin tinha outra raiz.

Quando o GET /admin/dashboard/stats extrai as palavras mais populares, ele aplica um filtro de últimos 7 dias. Só que a tabela em que esse filtro cai (category_attempt) não tem coluna de data própria. A data só existe do lado de learning_attempt, que entra no join. Logo, o Postgres não tem como recortar category_attempt por data antecipadamente, e precisa varrer o histórico inteiro. Por melhor que seja o índice, não há como tornar esse filtro seletivo.

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

O statement_timeout é de 8.000 milissegundos. 8.009 milissegundos. Morreu por 9 milissegundos de diferença. Era um full scan sem relação nenhuma com regiões, do tipo que estoura fatalmente algum dia, quando a tabela crescer.

Dos quatro alertas, três tinham uma raiz comum e um não tinha. Quatro alertas aparecerem na mesma tela não quer dizer que a causa seja uma só.

Uma hipótese descartada

Havia um suspeito bastante plausível: o cron de device-cleanup que roda pouco antes da rajada das 06:00 estaria causando contenção de lock. Os horários batiam, e a coisa soava bem convincente.

Varri os logs das duas regiões na janela das 05:30 às 06:15. Nenhum log relacionado ao cron. Conferindo o caminho do Device.updateMany que estava lento, não era o update em massa do cron, e sim /v2/public/auth/refresh, ou seja, requisições comuns de renovação de token de usuários. A hipótese foi descartada pela medição. Horários coincidirem é correlação; não estar no log é fato.

Dobramos as idas e voltas

A receita tem duas vertentes. Há o caminho de suportar o sintoma: aumentar o timeout para 8 segundos, engordar o pool, colocar retry. E há o caminho de eliminar o próprio custo: reduzir o número de idas e voltas.

Fizemos os dois. Envolver a transação de streak com withTxRetry é um curativo, mas era um curativo necessário. A receita de verdade, porém, era dobrar as idas e voltas.

A ferramenta já estava pronta. Numa migração de 27 de junho havia uma função server-side chamada create_practice_attempt_v1. Ela dobra o lock de sessão, a consulta, a inserção, a atualização dos metadados de sessão e a leitura dos agregados pré-computados numa única função SQL, resolvendo tudo numa ida e volta. E ainda é idempotente (chamada duas vezes com o mesmo client attempt id, na segunda vez devolve a linha existente e retorna inserted=false).

Só que a feature flag que liga essa função, PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, estava com valor padrão false e desligada em produção.

Em vez de eliminar uma região ou partir para active-active, o que fizemos foi ligar um interruptor que já estava instalado.

O canário: o que olhar para julgar

Ligamos a flag só em eu-west. Deixamos us-east desligada, como grupo de controle. Subimos da task definition 786 para a 787 e fizemos deploy rolling.

O ponto central desta história é qual métrica usar para julgar. Latência é armadilha. Se você publica num horário de tráfego calmo, o p95 melhora mesmo sem consertar nada. E, de fato, a latência melhorou. O p50 caiu de 2.784ms para abaixo de 2 mil ms. Só que isso é evidência fraca.

Em vez disso, olhei o número de queries por requisição.

antes   n=85   avg query_count = 22.0
depois  n=49   avg query_count = 15.3

O número de queries é uma métrica por requisição, indiferente à carga. Com muito ou pouco tráfego, quantas queries uma requisição dispara é decidido pelo caminho do código. De 22 para 15,3: cerca de 7 a menos. E esses 7 batem exatamente com a quantidade da lista de queries que dobramos numa única função (lock de sessão + consulta + inserção + metadados de sessão + leitura dos agregados pré-computados). A prova de que o caminho do código realmente mudou é esse número. Não a latência.

A amostra pós-deploy é de 49 requisições em 15 minutos. Nessa janela não houve nenhum 5xx nem P2028, mas eu não medi lado a lado o número de erros de uma janela "pré-deploy" do mesmo dia e do mesmo tamanho. Essa flag dobra apenas a gravação da tentativa. A transação de streak continua atravessando a região. Zero P2028 naquela janela quer dizer que tivemos sorte, não é prova.

O deploy deu certo, mas a flag quase desapareceu

O jeito como ligamos o canário tinha um preço. A 787 é uma task definition registrada na mão, pelo console. No próximo deploy oficial, o pipeline de CD sobrescreve com uma task definition sem a flag. Não é fatal (ao sobrescrever, volta para o OFF seguro). Só que a melhoria some em silêncio.

Então era preciso promover isso para o terraform, e aqui apareceu a segunda armadilha. O workflow do terraform faz apply só de staging no push para develop, e produção só no push para main. Só que staging não tem, de saída, a região eu-west. Ou seja, mergear em develop um PR que carrega uma mudança de produção em eu-west não faz absolutamente nada. Era preciso trocar a base para main.

Havia uma terceira armadilha. Mergeando direto em main, o develop fica para trás e, se não houver o merge de volta, a próxima release reverte essa mudança. Foi preciso abrir um PR de back-merge separado.

"O terraform apply passou" e "chegou em produção" são frases diferentes.

O que ficou

Quando chega um alerta de "banco fora do ar", o primeiro lugar a abrir são as métricas do banco. O nome do alerta foi dado pelo código que o disparou, não pela causa. Nosso health check tinha até um pool dedicado, isolado do pool do app, e mesmo assim travou junto com o app porque o caminho até o banco era o mesmo. Isolar não é só separar recursos: é separar caminhos também.

Aumentar o timeout de 5 para 8 segundos faz o alerta daquele dia parar. Mas a requisição continua atravessando o Atlântico vinte e cinco vezes. Basta o tráfego crescer um pouco e 8 segundos também ficam curtos. É melhor decidir de antemão se você vai suportar o sintoma ou eliminar o custo. Se o custo é "número x distância", o que se deve reduzir é o número.

Latência oscila com a carga; métricas por requisição não oscilam. Antes de publicar uma correção de performance e relaxar porque o p95 melhorou, veja se o número de coisas que uma requisição faz realmente diminuiu. Esse número é o mesmo, quer você publique de madrugada, quer publique na hora do almoço.

Eu contei o número de idas e voltas e peguei a latência por ida e volta de um comentário no código. Esses dois comentários diziam valores diferentes. Ainda bem que a conclusão não mudou, mas da próxima vez ela pode mudar. Número que não foi medido, escreva que não foi medido.