Descobrir onde está a lentidão, em vez de adivinhar
Hoje vais aprender a ouvir a tua aplicação: medir o que ela faz com métricas, seguir um pedido de ponta a ponta, ver para onde vai o tempo do processador e a memória, e encontrar os erros mais comuns em aplicações Spring. Sem magia, com ferramentas que vêm com o próprio Java.
- Expor métricas e saúde com o Actuator e o Micrometer
- Seguir pedidos com tracing distribuído
- Gravar e ler perfis com JFR e flame graphs
- Perceber o heap, o Garbage Collector e os heap dumps
- Depurar localmente, remotamente e dentro do Spring
- Diagnosticar N+1, pools esgotados, deadlocks e memory leaks
Não adivinhes: mede
Quando uma aplicação está lenta, a tentação é mudar logo código «que parece lento». Quase sempre, o culpado está noutro sítio. Estudos e a experiência de equipas grandes dizem o mesmo: os programadores acertam muito pouco quando tentam adivinhar o bottleneck.
Um bottleneck (gargalo) é o ponto que limita a velocidade de todo o sistema, como o gargalo de uma garrafa limita a velocidade a que a água sai, por maior que seja a garrafa.
Se fores ao médico com dores, ele não te opera logo. Primeiro mede a febre e a tensão (métricas), pergunta o que aconteceu (logs), pede uma TAC para ver por dentro (profiling) e só depois decide. Com software é igual.
Os três pilares da observabilidade
Observabilidade é a capacidade de perceber o que se passa dentro de um sistema olhando apenas para o que ele emite para fora.
O que vais ver nesta sessão
Spring Boot Actuator: o painel de bordo
O Actuator acrescenta à tua aplicação uma série de endereços (endpoints) que mostram o seu estado por dentro: se está saudável, quanta memória usa, que threads estão a correr, que configuração tem. É como o painel de um carro.
Ativar
Os endpoints que mais vais usar
| Endpoint | Para que serve |
|---|---|
/actuator/health | Está viva? A base de dados responde? O disco tem espaço? Usado por Kubernetes e balanceadores. |
/actuator/metrics | Lista de todas as métricas; /metrics/{nome} mostra uma em detalhe. |
/actuator/prometheus | As mesmas métricas no formato que o Prometheus recolhe. |
/actuator/loggers | Ver e mudar o nível de log em tempo real, sem reiniciar. |
/actuator/threaddump | Fotografia de todas as threads: o que cada uma está a fazer neste instante. |
/actuator/heapdump | Descarrega um ficheiro com toda a memória da aplicação. Pesado! |
/actuator/conditions, /beans | Que auto-configurações se aplicaram e que beans existem. |
Experimenta. Repara que podes mudar o nível de log com um POST, e o pedido seguinte já mostra outro detalhe.
O heapdump pode conter palavras-passe e dados pessoais que estavam em memória. O env mostra configurações. Nunca exponhas o Actuator à internet: usa uma porta de gestão separada, protege com Spring Security (papel ACTUATOR) e expõe só o necessário.
Métricas com Micrometer
O Micrometer é para as métricas o que o SLF4J é para os logs: uma fachada. Escreves o código uma vez e ele exporta para Prometheus, Datadog, New Relic, CloudWatch… O Spring Boot já mede sozinho imensa coisa (pedidos HTTP, JVM, pools, caches). Tu acrescentas as métricas de negócio.
Os três tipos que precisas de conhecer
Atalhos com anotações
Para @Timed funcionar fora dos controllers, regista um bean TimedAspect; para @Observed, um ObservedAspect (ambos precisam de spring-boot-starter-aop).
Podes acrescentar etiquetas (tags) às métricas, como metodo=cartao. Mas nunca uses valores com milhares de possibilidades (id do cliente, email, URL completo): cada valor diferente cria uma série nova e o sistema de métricas fica sem memória. Isto chama-se explosão de cardinalidade.
Ver tudo num painel: Prometheus + Grafana
/actuator/prometheusNo Grafana, importa o painel público «JVM (Micrometer)» (id 4701) e tens memória, GC, threads e pedidos HTTP em 2 minutos.
Tracing distribuído: seguir um pedido de ponta a ponta
Numa arquitetura com vários serviços, um clique do utilizador pode passar por cinco aplicações. Se demorar 3 segundos, onde se perdeu o tempo? O tracing responde a isso.
- Trace
- A viagem completa de um pedido. Tem um identificador único (
traceId). - Span
- Um troço dessa viagem: uma chamada HTTP, uma consulta SQL. Tem início, duração e um
spanId. - Propagação
- O
traceIdviaja nos cabeçalhos HTTP (traceparent) de serviço em serviço.
Assim aparece um trace numa ferramenta como Jaeger, Zipkin ou Grafana Tempo:
Configurar no Spring Boot 3
O Spring instrumenta sozinho os pedidos HTTP recebidos, as chamadas feitas com RestClient/WebClient (desde que construídos a partir do builder injetado pelo Spring), o JDBC (com a biblioteca datasource-micrometer) e os métodos com @Observed.
Logs que se ligam aos traces
Com o padrão acima, cada linha de log leva o traceId. Quando um cliente se queixa, procuras o traceId e vês todas as linhas daquele pedido, em todos os serviços.
O traceId vive no MDC, que está agarrado à thread. Lembras-te da sessão 1? Em @Async precisas do ContextPropagatingTaskDecorator, senão os logs da outra thread aparecem sem traceId.
As métricas dizem que há lentidão; os logs dizem o que aconteceu. O trace mostra cada troço do pedido com a sua duração, por isso aponta diretamente onde está o tempo.
Profiling: radiografia ao código
As métricas e os traces dizem-te que o endpoint /encomendas está lento. Mas que método, que linha? Para isso usa-se um profiler: uma ferramenta que observa a aplicação a correr e regista onde o processador passa o tempo e quem cria objetos na memória.
Sampling vs. instrumentação
| Sampling (amostragem) | Instrumentação | |
|---|---|---|
| Como funciona | Várias vezes por segundo, tira uma «fotografia» do que cada thread está a fazer. | Mete código de medição à entrada e saída de cada método. |
| Analogia | Espreitar a cozinha de 10 em 10 segundos e anotar o que cada cozinheiro faz. | Pôr um cronómetro em cada tarefa de cada cozinheiro. |
| Peso na aplicação | Baixo (1–2%). Seguro em produção. | Alto. Distorce os resultados. Só em desenvolvimento. |
| Precisão | Estatística: ótimo para encontrar os «grandes consumidores». | Exata, incluindo contagem de chamadas. |
As ferramentas
.jfr. Tem um «Automated Analysis» que aponta problemas.Gravar com o JFR
settings=profile recolhe mais detalhe (com um pouco mais de custo) do que o perfil default, que é o indicado para gravação contínua em produção.
Ler um flame graph
Um flame graph mostra milhares de amostras numa só imagem. As regras de leitura são poucas:
- Cada retângulo é um método. Em baixo está quem chama; por cima, quem é chamado.
- A largura é a percentagem de amostras em que o método aparecia. Mais largo = mais tempo de CPU.
- A cor não significa nada de especial (só ajuda a distinguir). O eixo horizontal não é o tempo: os métodos estão por ordem alfabética.
- Procura «planaltos» largos no topo: é aí que o processador está realmente ocupado (o self time).
Clica num retângulo para fazer zoom. Clica na base para voltar.
Quase metade do tempo está em Encomenda.getCliente → carregamento lazy do Hibernate, chamado dentro de um ciclo. É o problema N+1, que vais resolver no módulo 2.4. E repara no String.format dentro do cálculo de preços: pequeno mas fácil de eliminar.
Memória: o heap e o Garbage Collector
Cada new cria um objeto numa zona de memória chamada heap. Em Java não libertas memória à mão: o Garbage Collector (GC, «recolector de lixo») encontra os objetos que já ninguém usa e liberta o espaço.
Os clientes (o teu código) vão pedindo pratos (objetos). O GC passa pelas mesas e leva os pratos que já ninguém está a usar. Se ninguém largar os pratos, as mesas enchem e o restaurante pára: é o OutOfMemoryError.
Gerações: a maioria dos objetos morre jovem
Que Garbage Collector escolher?
| GC | Característica | Quando usar |
|---|---|---|
| G1 (defeito) | Equilíbrio entre throughput e pausas curtas (objetivo: 200 ms). | A maioria das aplicações Spring. Não mexas sem motivo. |
| ZGC (geracional) | Pausas abaixo de 1 ms, mesmo com heaps enormes. Gasta um pouco mais de CPU. | APIs sensíveis à latência (p99 apertados), heaps grandes. -XX:+UseZGC |
| Parallel | Máximo throughput, pausas mais longas. | Processamento em lote, onde as pausas não importam. |
| Serial | Uma thread, simples. | Contentores minúsculos (1 CPU, pouca memória). |
Vê o heap a respirar (e a sufocar)
Um heap saudável faz «dentes de serra»: enche, o GC limpa, volta ao nível base. Com um memory leak (fuga de memória), o nível base sobe sempre, os GCs ficam cada vez mais frequentes e, no fim, a aplicação morre.
Ler os logs do GC
Lê-se assim: 301M->118M(512M) 6.214ms = antes da recolha havia 301 MB ocupados, depois ficaram 118 MB, o heap tem 512 MB e a pausa durou 6 ms. A última linha é um sinal de alarme: um Full GC de 812 ms que só libertou 27 MB. A memória está quase toda presa.
O GCeasy e o GCViewer transformam o gc.log em gráficos. Em produção, as métricas jvm.gc.pause e jvm.memory.used do Micrometer dão-te o mesmo no Grafana.
Heap dumps e Eclipse MAT
Um heap dump é uma fotografia de todos os objetos em memória num instante. Abres o ficheiro .hprof no Eclipse Memory Analyzer (MAT) para descobrir quem está a ocupar a memória.
- Shallow size
- Memória ocupada pelo próprio objeto (os seus campos).
- Retained size
- Memória que seria libertada se esse objeto desaparecesse: ele e tudo o que só ele segura. É este o número que interessa.
- Dominator tree
- Lista dos objetos que «seguram» mais memória. O primeiro sítio a olhar.
- GC root
- Ponto de partida que mantém objetos vivos: variáveis estáticas, threads ativas, variáveis locais.
| Dominator tree (exemplo) | Shallow | Retained | % |
|---|---|---|---|
pt.loja.RelatorioService | 24 B | 312 MB | 71% |
↳ java.util.HashMap (campo cacheRelatorios) | 48 B | 312 MB | 71% |
↳ 184 220 × pt.loja.Relatorio | 32 B cada | ~1,7 KB cada | |
org.apache.catalina…StandardManager | 96 B | 21 MB | 5% |
O relatório «Leak Suspects» do MAT chegaria à mesma conclusão: um HashMap usado como cache, sem limite, dentro de um singleton.
Laboratório 2: gravar e analisar um perfil sob carga
Passos laboratório · 20 min
- Arranca a aplicação do curso com
-XX:StartFlightRecording=settings=profile,filename=lab.jfr,dumponexit=true. - Gera carga durante 60 s. Por agora basta um ciclo no terminal (na sessão 3 usarás o Gatling):
- Pára a aplicação e abre
lab.jfrno JDK Mission Control (ou arrasta para o IntelliJ). - Em Method Profiling, encontra o método com mais amostras. Em Memory → Allocations, encontra quem cria mais objetos.
- Em Automated Analysis, anota os avisos a vermelho.
- Escreve uma hipótese: «O bottleneck é X porque Y». Vais confirmá-la no módulo 2.4.
asprof -d 30 -f flame.html 4711 grava 30 segundos e gera um flame graph interativo em HTML. Com -e alloc mostra alocações em vez de CPU; com -e wall inclui o tempo à espera (útil para I/O).
Debugging: parar o tempo e olhar lá para dentro
Um debugger permite pausar o programa numa linha à tua escolha e inspecionar todas as variáveis, avançando uma linha de cada vez. É a ferramenta mais poderosa para perceber erros de lógica.
Os comandos essenciais
| Ação | IntelliJ (Win/Linux) | O que faz |
|---|---|---|
| Breakpoint | clica na margem | O programa pára quando chegar a esta linha. |
| Step Over | F8 | Executa a linha e pára na seguinte. |
| Step Into | F7 | Entra dentro do método chamado na linha. |
| Step Out | Shift+F8 | Termina o método atual e volta a quem o chamou. |
| Resume | F9 | Continua até ao próximo breakpoint. |
| Evaluate Expression | Alt+F8 | Corre qualquer expressão Java no contexto atual. |
Breakpoints inteligentes
encomenda.getId() == 981. Só pára no caso que te interessa, mesmo num ciclo de 10 000 voltas.+ → Java Exception Breakpoint. Pára no momento exato em que a exceção é lançada.Debugging remoto (servidor ou Docker)
Podes ligar o debugger do teu IDE a uma JVM que corre noutra máquina ou num contentor, através do protocolo JDWP.
Quem se ligar à porta JDWP consegue executar qualquer código no servidor. Usa só em desenvolvimento, ou através de um túnel SSH. E lembra-te: num breakpoint, todas as threads daquele pedido param, e os timeouts disparam. Em servidores partilhados, prefere logpoints.
Debugging específico do Spring
«Porque é que este bean não foi criado?»
Aqui o Spring explica que a cache Redis não foi configurada porque não encontrou uma ligação ao Redis (falta a dependência ou a configuração). O mesmo relatório está em /actuator/conditions.
«Porque é que a minha transação não fez rollback?»
| Sintoma | Causa mais provável |
|---|---|
O @Transactional parece ignorado | Auto-invocação (this.metodo()), método private ou classe não gerida pelo Spring. Tal como no @Async: é um proxy. |
| Não faz rollback | Foi lançada uma exceção checked (o rollback por defeito só acontece com RuntimeException) ou a exceção foi apanhada num catch. Usa rollbackFor = Exception.class. |
LazyInitializationException | Acedeste a uma relação lazy depois de a transação fechar. |
Logging estratégico
Mudar o nível de log em tempo real (com o Actuator) é uma ferramenta de debugging em produção: ligas DEBUG num pacote durante 5 minutos, recolhes o que precisas e voltas a INFO.
Logar SQL com parâmetros em produção enche discos e pode expor dados pessoais. E concatenar texto num log desligado continua a gastar CPU: escreve log.debug("Encomenda {}", id) e não log.debug("Encomenda " + id).
Problema clássico 1: o N+1 da base de dados
Pedes a lista de 100 encomendas (1 consulta). Depois, para mostrar o nome do cliente de cada uma, o Hibernate faz uma consulta por encomenda (N = 100 consultas). Total: N+1 = 101 idas à base de dados, quando uma bastava.
Tens uma lista de compras com 100 artigos. Em vez de pegar num carrinho e trazer tudo de uma vez, vais ao supermercado, trazes um artigo, voltas a casa, e repetes 100 vezes. Cada ida é rápida, mas o total é enorme.
Experimenta as diferentes soluções e vê o SQL gerado:
| Solução | Vantagem | Cuidado |
|---|---|---|
JOIN FETCH / @EntityGraph | Uma só consulta. | Não junte duas coleções (@OneToMany) no mesmo fetch: produto cartesiano. Com paginação, o Hibernate pode paginar em memória. |
@BatchSize | Simples, funciona com paginação e coleções. | Ainda faz algumas consultas. |
| Projeções DTO | Traz só o necessário. Normalmente a mais rápida para listagens. | Os objetos não são entidades (não se podem alterar e gravar). |
Ativa hibernate.generate_statistics em desenvolvimento e olha para «JDBC statements executed». Em testes, bibliotecas como datasource-proxy ou Hypersistence Utils deixam-te escrever assertSelectCount(1) para que um N+1 parta o build.
Problema clássico 2: o pool de ligações esgotado
Abrir uma ligação à base de dados é lento (autenticação, rede). Por isso o Spring Boot usa um pool de ligações, o HikariCP, que mantém um número fixo de ligações abertas e empresta-as aos pedidos. Por defeito são 10.
O pool é um parque com 10 lugares. Cada pedido estaciona enquanto fala com a base de dados. Se chegarem 100 carros e cada um ficar estacionado muito tempo (consulta lenta, ou transação que inclui uma chamada HTTP), os outros 90 ficam na fila. Se esperarem mais do que o connectionTimeout (30 s por defeito), desistem com erro.
Causas típicas e soluções
| Causa | Solução |
|---|---|
| Consultas lentas (sem índice, N+1) | Corrigir as consultas. Libertam a ligação mais depressa. |
Chamadas HTTP dentro de @Transactional | Fazer a chamada externa fora da transação. A ligação fica presa enquanto esperas pelo outro serviço! |
spring.jpa.open-in-view=true (defeito) | Mantém a ligação até a resposta HTTP ser escrita. Desliga com false. |
| Ligações nunca devolvidas (leak) | leak-detection-threshold mostra no log a stack trace de quem a pediu. |
| Virtual threads sem limite | Milhares de pedidos competem por 10 ligações. Limita a concorrência (semáforo, bulkhead) ou ajusta o pool. |
A base de dados tem núcleos e discos limitados. A fórmula de partida sugerida pela equipa do HikariCP é ligações ≈ (núcleos da BD × 2) + discos. Um pool de 200 ligações costuma tornar tudo mais lento. Vais medir isto na sessão 3.
Monitoriza com as métricas hikaricp.connections.active, hikaricp.connections.pending e hikaricp.connections.acquire. Se o pending estiver sempre acima de zero, tens fila no parque.
Problema clássico 3: threads presas
A aplicação deixa de responder, mas o CPU está a 0%. As threads estão todas à espera de alguma coisa. Um thread dump mostra exatamente o quê.
Tira 3 dumps com 5 a 10 segundos de intervalo. Uma thread que aparece no mesmo sítio nos três está mesmo presa; num só dump, podia estar só de passagem.
Estados das threads
| Estado | Significa |
|---|---|
RUNNABLE | A trabalhar (ou a ler da rede, que também aparece assim). |
BLOCKED | À espera de entrar num synchronized que outra thread tem. |
WAITING / TIMED_WAITING | À espera de um sinal, de um join, de uma ligação do pool, de um sleep. |
Um deadlock apanhado em flagrante
A JVM deteta deadlocks com synchronized sozinha e diz-te as duas threads e a linha. A correção: bloquear as contas sempre pela mesma ordem (por exemplo, pelo id mais baixo primeiro).
Em Java 21–23, procura o evento JFR jdk.VirtualThreadPinned ou arranca com -Djdk.tracePinnedThreads=full. Se aparecerem muitos, há synchronized com esperas lá dentro a anular o benefício das virtual threads.
Problema clássico 4: memory leaks em Java
O GC só liberta objetos a que ninguém chega. Um memory leak em Java é quase sempre um objeto que continua acessível sem que precises dele: o GC não o pode levar.
Correção: usar @Cacheable com Caffeine e maximumSize (sessão 1). Um campo num singleton vive enquanto a aplicação viver.
As threads do Tomcat são reutilizadas e vivem para sempre. O que puseres num ThreadLocal e não removeres fica agarrado à thread, e pode até passar para o pedido de outro utilizador! Correção: try { … } finally { atual.remove(); }, num filtro.
Cada registo guarda uma referência ao objeto, que nunca será recolhido. Correção: remover o ouvinte quando já não é preciso, ou usar os eventos do Spring (ApplicationEventPublisher e @EventListener), que gerem o ciclo de vida por ti.
Laboratório 3: diagnosticar e corrigir
Passos laboratório · 20 min
O projeto do curso tem dois defeitos introduzidos de propósito: um N+1 em GET /encomendas e um leak em GET /relatorios?filtro=….
- Arranca com
-Xmx256m -XX:+HeapDumpOnOutOfMemoryErrore as estatísticas do Hibernate ligadas. - Chama
/encomendasuma vez e conta as consultas no log. Corrige com@EntityGraphe confirma que passa a 1. - Gera 50 000 pedidos a
/relatorioscom filtros diferentes (filtro=$RANDOM) até rebentar. - Abre o
.hprofno Eclipse MAT, corre «Leak Suspects» e identifica o campo culpado. - Corrige com Caffeine (
maximumSize=1000), repete o teste e mostra no Grafana que o heap passou a fazer dentes de serra.
Exercícios
1. Uma métrica de negócio fácil
Cria um contador loja.pagamentos com a tag resultado (sucesso ou falha) e incrementa-o no serviço de pagamentos.
Ver solução
2. Ler um log de GC médio
O que concluis destas linhas? GC(90) Pause Young 480M->470M(512M) 31ms, GC(91) Pause Young 482M->474M(512M) 34ms, GC(92) Pause Full 505M->498M(512M) 1.4s.
Ver solução
Cada recolha liberta muito pouco (10 MB, 8 MB, 7 MB) e o nível depois do GC está perto do máximo. A memória está quase toda ocupada por objetos vivos: ou o heap é demasiado pequeno para a carga, ou (mais provável, se for crescendo ao longo do tempo) há um memory leak. Próximo passo: heap dump e Eclipse MAT.
3. Transação que segura a ligação médio
Encontra o problema e reescreve:
Ver solução
A ligação à base de dados fica ocupada durante a chamada HTTP. Com 10 ligações e pagamentos de 2 s, o máximo são 5 checkouts por segundo para a aplicação inteira. Separa: lê o carrinho, cobra fora de transação e só depois abre uma transação curta para gravar.
Resumo da sessão
O essencial em 10 pontos
- Mede antes de otimizar: métricas dizem que, logs dizem o quê, traces dizem onde.
- O Actuator expõe saúde, métricas, loggers e dumps. Protege-o sempre.
- Micrometer:
Countersó sobe,Gaugesobe e desce,Timermede durações. Cuidado com tags de alta cardinalidade. - Micrometer Tracing + OpenTelemetry ligam logs e spans pelo
traceId. - Profilers por amostragem (JFR, async-profiler) são seguros em produção.
- Num flame graph, largura = tempo; procura os planaltos largos no topo.
- Heap saudável faz dentes de serra; nível base sempre a subir indica leak.
- Heap dump + Eclipse MAT: olha para o retained size e para a dominator tree.
- N+1: resolve com
JOIN FETCH,@EntityGraph,@BatchSizeou projeções. - Pool de ligações esgotado: consultas lentas, HTTP dentro de transações,
open-in-view.
Glossário
- Bottleneck
- O ponto que limita o desempenho de todo o sistema.
- Observabilidade
- Capacidade de perceber o estado interno de um sistema pelas suas métricas, logs e traces.
- Span
- Troço de um trace com início e duração.
- Profiler
- Ferramenta que mede onde se gasta CPU e memória.
- JFR
- Java Flight Recorder, o gravador de eventos incorporado na JVM.
- Flame graph
- Visualização de stack traces amostradas; a largura é proporcional ao tempo.
- Heap
- Zona de memória onde vivem os objetos.
- GC
- Garbage Collector: liberta objetos inacessíveis.
- Retained size
- Memória que seria libertada se um objeto desaparecesse.
- N+1
- 1 consulta para a lista + 1 por cada elemento.
- Thread dump
- Fotografia do estado de todas as threads.
Trabalho de casa
Painel de observabilidade. Com docker compose, põe a correr Prometheus, Grafana e Jaeger (ou Grafana Tempo) ao lado da aplicação do curso. Cria um painel com: pedidos por segundo, p95 do tempo de resposta por endpoint, ligações Hikari ativas e pendentes, heap usado e pausas de GC. Exporta o painel em JSON.
Leitura: documentação Spring Boot, secções «Production-ready Features» → «Metrics» e «Tracing».
Na próxima sessão: vais pôr a aplicação sob carga a sério e usar este painel para encontrar o limite dela.