# Aula 15 - APM: De "está lento" para "aqui está o N+1" (Grafana Tempo + OpenTelemetry) Métricas dizem **O QUE** está errado. Traces dizem **POR QUE**. ## O problema que esta aula resolve Cenário real: uma aplicação começa rápida. Um agente de IA (ou um dev apressado) usa um ORM e mete um N+1. A base de dados cresce. A latência sobe de 50ms para 500ms ao longo de um mês. O Victoria Metrics (aula-12) mostra que a latência subiu. Mas **não mostra por quê**. Você sabe que está lento — mas é o banco? A rede? Um serviço externo? Um loop de queries? Sem traces, o debug é: ``` 1. Olhar logs (milhares de linhas) 2. Adicionar console.log/dd() no código 3. Deploiar versão com debug 4. Esperar acontecer de novo 5. Repetir ``` Com traces, o debug é: ``` 1. Abrir Grafana 2. Clicar no spike de latência 3. Ver o trace: 1 request HTTP → 147 queries SQL 4. Encontrar o N+1 ``` **Diferença: horas/dias vs. 30 segundos.** ## O Limiar de Doherty Em 1982, Walter Doherty e Ahrvind Thadani publicaram um estudo na IBM Systems Journal mostrando que quando o tempo de resposta de um sistema passa de **400ms**, o usuário perde o senso de "fluxo" — a interação deixa de parecer instantânea. ``` 0-100ms → Instantâneo (o usuário nem percebe) 100-400ms → Rápido (o usuário nota mas tolera) 400ms-1s → Lento (perde o "flow state", perde engagement) 1s+ → Quebrado (o usuário sai) ``` O perigo do intervalo 100-400ms → 400ms-1s: o usuário **não reclama**. Ele simplesmente usa menos. A retenção cai silenciosamente. Nenhuma métrica de infraestrutura (CPU, RAM, disco) vai detectar isso — tudo parece normal. **O que detecta: latência por rota medida com OpenTelemetry + alertas no Victoria Metrics.** ## O que instalamos ``` ┌─────────────────────────────────────────────────────────────────┐ │ Stack Completo │ │ │ │ App (Node.js / Laravel / qualquer linguagem) │ │ │ │ │ │ OpenTelemetry SDK (auto-instrumentação) │ │ │ │ │ ├──► Métricas ──► Victoria Metrics (aula-12, já instalado) │ │ │ └──► Grafana: dashboard RED │ │ │ │ │ └──► Traces ──► Grafana Tempo (esta aula) │ │ └──► Grafana: trace view │ │ │ │ Grafana conecta os dois: │ │ dashboard latência (VM) → clica → abre trace (Tempo) │ │ → vê cada SQL query │ │ → encontra o N+1 │ └─────────────────────────────────────────────────────────────────┘ ``` ### Escolha do Tempo (e não Jaeger, SigNoz, etc.) | | Jaeger | SigNoz | Grafana Tempo | |---|---|---|---| | **Storage** | Cassandra/Elasticsearch | ClickHouse | Local disk ou S3 (sem DB) | | **RAM mínima** | ~512Mi+ | ~3Gi | ~256Mi | | **UI** | Própria (mais uma URL) | Própria | **Grafana (já temos)** | | **Query language** | Tags básicas | ClickHouse SQL | **TraceQL** | | **Metrics↔Traces** | Manual | Próprio | **Nativo no Grafana** | Tempo segue a mesma filosofia do workshop: **single binary, sem dependências extras, integra com o que já temos**. ## Conceitos ### O que é um Trace Um trace é a **jornada completa** de um request pelo sistema: ``` Trace: GET /api/users (total: 487ms) │ ├── [Span] HTTP GET /api/users .................. 487ms │ ├── [Span] middleware.auth .................. 2ms │ ├── [Span] UserController.index ............ 480ms │ │ ├── [Span] SELECT * FROM users ......... 3ms ← 1 query │ │ ├── [Span] SELECT * FROM posts WHERE ... 3ms ← N+1 começa aqui │ │ ├── [Span] SELECT * FROM posts WHERE ... 3ms │ │ ├── [Span] SELECT * FROM posts WHERE ... 3ms │ │ ├── ... (x147 vezes) │ │ └── [Span] SELECT * FROM posts WHERE ... 3ms ← 147 queries │ └── [Span] JSON serialize .................. 5ms └── total SQL time: 441ms / 147 queries ``` Cada caixa é um **span**. O trace é a árvore completa. ### RED Method (métricas por rota) O padrão ouro de monitoramento de aplicações: | Métrica | O que mede | Alerta quando | |---------|-----------|---------------| | **R**ate | Requests por segundo por rota | Drop súbito (app caiu?) | | **E**rrors | % de respostas 5xx por rota | > 1% (algo quebrou) | | **D**uration | Latência p50, p95, p99 por rota | p95 > 400ms (limiar de Doherty) | OpenTelemetry gera essas métricas automaticamente. Victoria Metrics armazena. Grafana mostra. ### Diferença: Métricas vs Traces | | Métricas (Victoria Metrics) | Traces (Tempo) | |---|---|---| | **Granularidade** | Agregado (p99 de todos os requests) | Individual (cada request) | | **Custo** | Baixo (números comprimidos) | Alto (cada span é um evento) | | **Responde** | "A latência da rota /api/users está alta" | "Este request específico fez 147 queries SQL" | | **Analogia** | Termômetro (temperatura do corpo) | Raio-X (o que está causando a febre) | **Use métricas pra detectar. Use traces pra diagnosticar.** ## Pré-requisitos - Cluster Kubernetes Hetzner (aula-08) - Victoria Metrics + Grafana (aula-12) - kubectl e helm instalados ## Estrutura ``` aula-15/ ├── README.md ├── setup.sh # Instala Tempo + OTel Collector ├── cleanup.sh │ ├── tempo-values.yaml # Config do Grafana Tempo ├── otel-collector-values.yaml # Config do OpenTelemetry Collector │ ├── demo-app/ # App Node.js com N+1 intencional │ ├── Dockerfile │ ├── app.js # Servidor com rotas rápidas e lentas │ ├── package.json │ └── k8s/ │ ├── deployment.yaml │ ├── service.yaml │ └── ingress.yaml │ ├── dashboards/ │ └── red-dashboard.json # Dashboard RED pra Grafana │ └── alerts/ └── latency-alerts.yaml # VMRule: alerta quando p95 > 400ms ``` ## Instalação ```bash cd aula-15 export KUBECONFIG=$(pwd)/../aula-08/kubeconfig ./setup.sh ``` O script instala: 1. **Grafana Tempo** — backend de traces (namespace: monitoring) 2. **OpenTelemetry Collector** — recebe traces das apps e envia pro Tempo 3. **Demo app** — aplicação Node.js com N+1 intencional 4. **Dashboard RED** — latência/rate/errors por rota 5. **Alerta de latência** — dispara quando p95 > 400ms (Doherty) ## Arquitetura ``` ┌──────────────────────────────────────────────────────────────┐ │ Namespace: demo │ │ │ │ ┌──────────────────────────────────┐ │ │ │ demo-app (Node.js) │ │ │ │ @opentelemetry/auto-instrument │ │ │ │ │ │ │ │ GET /fast → 1 SQL query │ │ │ │ GET /slow → N+1 (100+ SQL) │ │ │ └──────────┬───────────────────────┘ │ │ │ OTLP (gRPC :4317) │ └─────────────┼────────────────────────────────────────────────┘ │ ▼ ┌──────────────────────────────────────────────────────────────┐ │ Namespace: monitoring │ │ │ │ ┌────────────────────┐ │ │ │ OTel Collector │ │ │ │ │ │ │ │ Recebe OTLP ──────┬──► Grafana Tempo (traces) │ │ │ │ │ │ │ Gera métricas ─────┴──► Victoria Metrics (RED metrics) │ │ └────────────────────┘ │ │ │ │ ┌────────────────────┐ │ │ │ Grafana │ │ │ │ │ │ │ │ Dashboard RED ◄──── Victoria Metrics │ │ │ (latência p95) │ │ │ │ │ │ │ │ │ click spike │ │ │ │ ▼ │ │ │ │ Trace view ◄─────── Tempo │ │ │ (147 SQL spans) │ │ │ └────────────────────┘ │ └──────────────────────────────────────────────────────────────┘ ``` ### Por que o OTel Collector? A app poderia enviar direto pro Tempo. Mas o Collector faz duas coisas cruciais: 1. **Deriva métricas dos traces** — gera automaticamente `http_server_request_duration` (histograma por rota) sem instrumentar a app pra métricas separadamente 2. **Desacopla** — a app envia pra um endpoint fixo (`otel-collector:4317`), o backend pode mudar sem tocar na app ## A Demo App: node-bugado-n1 Uma aplicação Node.js simples com duas rotas: ```javascript // GET /fast — 1 query, resposta em ~5ms app.get('/fast', async (req, res) => { const users = await db.query('SELECT * FROM users LIMIT 10'); res.json(users); }); // GET /slow — N+1, resposta em ~500ms app.get('/slow', async (req, res) => { const users = await db.query('SELECT * FROM users'); // N+1: uma query por usuário pra buscar posts for (const user of users) { user.posts = await db.query('SELECT * FROM posts WHERE user_id = ?', [user.id]); } res.json(users); }); ``` O OpenTelemetry auto-instrumento captura **cada query SQL** como um span — sem mudar o código. ## Fluxo da demonstração ### 1. Gerar tráfego ```bash # Rota rápida (1 query) for i in $(seq 1 100); do curl -s https://demo.kube.quest/fast > /dev/null; done # Rota lenta (N+1) for i in $(seq 1 100); do curl -s https://demo.kube.quest/slow > /dev/null; done ``` ### 2. Ver no dashboard RED (Grafana) Abrir `https://grafana.kube.quest` → Dashboard "RED - Application": - **Rate**: `/fast` e `/slow` com ~100 requests cada - **Errors**: 0% (não é erro — é lentidão) - **Duration**: `/fast` p95 = 5ms, `/slow` p95 = 500ms O alerta "Doherty Threshold" dispara pra `/slow`. ### 3. Clicar no spike → ver o trace No gráfico de latência, clicar num ponto da rota `/slow`: - Grafana abre o trace no Tempo - Trace mostra: 1 span HTTP → 1 span Controller → **100 spans SQL** - Cada span SQL: `SELECT * FROM posts WHERE user_id = ?` - **N+1 encontrado em 30 segundos** ### 4. Comparar com `/fast` Clicar num ponto da rota `/fast`: - Trace mostra: 1 span HTTP → 1 span Controller → **1 span SQL** - `SELECT * FROM users LIMIT 10` - Latência: 5ms **A diferença é visual e imediata.** ## Alertas ### Doherty Threshold (latência > 400ms) ```yaml # alerts/latency-alerts.yaml apiVersion: operator.victoriametrics.com/v1beta1 kind: VMRule metadata: name: latency-alerts namespace: monitoring spec: groups: - name: application.latency rules: - alert: DohertyThresholdExceeded expr: | histogram_quantile(0.95, sum(rate(http_server_request_duration_seconds_bucket[5m])) by (le, http_route) ) > 0.4 for: 5m labels: severity: warning annotations: summary: "Rota {{ $labels.http_route }} acima do limiar de Doherty" description: "p95 = {{ $value | humanizeDuration }}. Acima de 400ms, usuários perdem o senso de fluxo." - alert: HighErrorRate expr: | sum(rate(http_server_request_duration_seconds_count{http_status_code=~"5.."}[5m])) by (http_route) / sum(rate(http_server_request_duration_seconds_count[5m])) by (http_route) > 0.01 for: 5m labels: severity: critical annotations: summary: "Rota {{ $labels.http_route }} com {{ $value | humanizePercentage }} de erros" ``` ## Quanto custa em recursos | Componente | Memory Request | Memory Limit | |------------|----------------|--------------| | Grafana Tempo | 256Mi | 512Mi | | OTel Collector | 128Mi | 256Mi | | Demo app | 64Mi | 128Mi | | **Total adicional** | **~448Mi** | **~896Mi** | Tempo armazena traces em disco (10Gi PVC). Retenção: 7 dias por padrão. ## Lições do Workshop 1. **Métricas ≠ Traces** — métricas são o termômetro, traces são o raio-X. Use os dois. 2. **O limiar de Doherty (400ms)** é onde a UX degrada silenciosamente. Meça latência por rota. 3. **N+1 é invisível sem traces** — a app não dá erro, o CPU não sobe, o disco não enche. Só o usuário sofre. 4. **OpenTelemetry é o padrão** — instrumenta uma vez, manda pra qualquer backend (Tempo, Jaeger, Datadog). 5. **OTel Collector como hub** — deriva métricas RED dos traces automaticamente. Uma instrumentação, dois sinais. 6. **Grafana conecta tudo** — métricas (Victoria Metrics) + traces (Tempo) na mesma UI, com correlação nativa. ## O que NÃO cobrimos (e por quê) | Tema | Por que não | Quando faz sentido | |------|------------|-------------------| | **Logs** (Loki/VictoriaLogs) | Logs são texto desestruturado — traces são melhores pra debug | Compliance, auditoria, erros não-HTTP | | **Distributed tracing multi-serviço** | Workshop tem apps simples | Quando tiver 5+ microserviços | | **Continuous Profiling** (Pyroscope) | Nível muito avançado | Quando traces não bastam (CPU profiling) | | **Real User Monitoring (RUM)** | Precisa de frontend instrumentado | SPA com métricas de UX | ## Cleanup ```bash ./cleanup.sh ``` Remove Tempo, OTel Collector e demo app. Victoria Metrics (aula-12) é mantido. ## Referências - [Grafana Tempo Docs](https://grafana.com/docs/tempo/latest/) - [OpenTelemetry Docs](https://opentelemetry.io/docs/) - [OpenTelemetry Node.js Auto-Instrumentation](https://opentelemetry.io/docs/languages/js/automatic/) - [RED Method (Tom Wilkie)](https://grafana.com/blog/2018/08/02/the-red-method-how-to-instrument-your-services/) - [Doherty Threshold (IBM, 1982)](https://jlelliotton.blogspot.com/p/the-economic-value-of-rapid-response.html) - [TraceQL (Grafana)](https://grafana.com/docs/tempo/latest/traceql/) - [Span Metrics via OTel Collector](https://opentelemetry.io/docs/collector/transforming-telemetry/)