Logs dizem o que aconteceu; traces dizem para onde o tempo foi

O curso anterior terminou com logs estruturados e correlacionados. Eles respondem o que aconteceu, em que ordem, com quem. Eis o que eles não respondem.

Uma pessoa relata que a página de Maestria está lenta. Seu log tem uma linha:

{"message":"request.completed","path":"/enrollment/mastery","status":200,"duration_ms":3840}

Três vírgula oito segundos. A linha está correta, completa e é inútil: ela diz que a requisição foi lenta e nada sobre qual parte dela foi lenta. Os tempos desta aula são inventados para mostrar o formato; as chamadas reais não são tão lentas.

Abra o Enrollment::UserGamificationQuery deste repositório e a ambiguidade fica concreta. Uma chamada a .call faz, no mínimo:

• ExperiencePoint.total_for(user.id): uma soma
• Level.ordered.to_a: um carregamento
• SkillRadarQuery.call(user:): outro objeto de consulta, com as consultas dele
• LeaderboardSnapshot.current_for("all_time"): uma busca do snapshot atual
• snapshot.entries.find_by(user_id:): a entrada do aluno nele
• snapshot.entries.count: uma contagem sobre todos os alunos ranqueados

São seis idas ao banco, mais o que o SkillRadarQuery faz por dentro, atrás de uma chamada de método e uma linha de log. Qual delas levou três segundos? O log não sabe dizer. Uma contagem sobre uma tabela grande de entradas e o que o SkillRadarQuery roda por dentro são os dois plausíveis, e adivinhar entre eles é como uma tarde desaparece.

O que é um trace

Um trace é a mesma requisição, dividida em intervalos cronometrados e aninhados chamados spans:

flowchart TB
  R["GET /enrollment/mastery — 3840ms"] --> C["MasteryController#show — 3800ms"]
  C --> Q["UserGamificationQuery.call — 3700ms"]
  Q --> S1["ExperiencePoint.total_for — 120ms"]
  Q --> S2["Level.ordered — 40ms"]
  Q --> S3["SkillRadarQuery.call — 300ms"]
  Q --> S4["LeaderboardSnapshot.current_for — 30ms"]
  Q --> S5["entries.find_by — 50ms"]
  Q --> S6["entries.count — 3100ms"]

Disposto numa linha do tempo, o mesmo trace é uma cascata: cada barra começa onde quem a chamou permite e dura o que durou.

GET /enrollment/mastery        |=========================================| 3840ms
  MasteryController#show       | ========================================| 3800ms
    UserGamificationQuery.call |  =======================================| 3700ms
      ExperiencePoint.total_for|  ==                                     |  120ms
      Level.ordered            |     =                                   |   40ms
      SkillRadarQuery.call     |      ====                               |  300ms
      Snapshot.current_for     |          =                              |   30ms
      entries.find_by          |           =                             |   50ms
      entries.count            |            ============================ | 3100ms

A resposta está visível: o entries.count levou três vírgula um segundos. Sem hipótese, sem bisseção, sem acrescentar logs de tempo e esperar acontecer de novo.

É essa a proposta inteira. Um trace transforma a requisição foi lenta em esta chamada foi lenta, e faz isso para uma requisição que já aconteceu.

Por que a parte distribuída

Um trace dentro de um processo é útil. Ele vira necessário quando o trabalho cruza uma borda: uma chamada HTTP a outro serviço, um job entregue a um worker, uma chamada a um provedor de pagamento. Cada uma dessas é uma caixa preta na sua própria contagem de tempo, e um trace distribuído as transforma em spans como quaisquer outros, com um identificador compartilhado atravessando junto.

Esta aplicação é um monólito modular, então as bordas que ela cruza são o banco, os jobs em segundo plano e o HTTP de saída. Isso já basta para o tracing valer a pena e para ensinar todos os conceitos. Os mesmos conceitos transferem direto para um sistema de doze serviços, que é onde você vai reencontrá-los.

Os três sinais

Eles se complementam, e nenhum substitui o outro. O padrão que emerge, que a aula 6 desenvolve, é: uma métrica alerta, um trace localiza, um log explica. Perder qualquer um faz os outros dois trabalharem mais.

Quanto isso custa

Pese isto antes de se comprometer:

• Custo de instrumentação: pequeno com instrumentação automática, mas todo span é uma alocação e um timestamp.
• Volume: toda requisição produz muitos spans. Em escala você precisa amostrar, que é a aula 4.
• Um backend: Jaeger, Tempo ou um fornecedor. Mais um sistema para rodar, ou mais uma conta.
• Atenção: um sistema de tracing que ninguém abre é um custo sem retorno. Times que o instalam sem decidir qual pergunta ele responde costumam acabar assim.

O que este curso cobre

1. Logs dizem o que aconteceu; traces dizem para onde o tempo foi (você está aqui).
2. Spans, traces e contexto.
3. Instrumentando uma aplicação Rails.
4. Amostragem, e o que ela custa.
5. Lendo um trace.
6. Os três sinais juntos.
7. Juntando tudo: tracing nesta aplicação.

Pontos-chave

• Uma linha de log informa que a requisição levou 3,8 segundos; ela não diz qual das dez operações levou.
• Um trace é uma requisição como árvore de spans cronometrados, o que localiza a lentidão sem reproduzi-la.
• A distribuição importa nas bordas de processo (serviços, jobs, chamadas de saída), onde a sua contagem de tempo fica cega.
• Métricas alertam, traces localizam, logs explicam; os três se complementam.
• Tracing custa sobrecarga, volume, um backend e a atenção para usá-lo.