Medir Antes de Otimizar — JFR, Mission Control e JMH

Como descobrir onde um programa realmente gasta tempo e memória, como gravar o que acontece dentro da JVM em produção, e como medir corretamente o efeito de uma otimização.

As duas últimas aulas abriram a JVM: carregamento de classes, JIT, pilha, heap e coletores. Mas saber como a máquina funciona não diz, por si só, por que um programa específico está lento. A intuição dos programadores sobre onde está o gargalo é famosa por errar, e a otimização feita no lugar errado não melhora nada e piora a legibilidade do código. Esta aula apresenta as ferramentas que substituem a intuição por dados. O JDK Flight Recorder grava o que acontece dentro da JVM com impacto mínimo, inclusive em produção, e o JDK Mission Control permite explorar essas gravações. O JMH é o padrão para medir o desempenho de um trecho de código sem se deixar enganar pelo JIT.

A regra de ouro

Donald Knuth escreveu, em 1974, a frase mais citada sobre desempenho: "a otimização prematura é a raiz de todo mal". A frase completa é mais precisa: "devemos esquecer as pequenas eficiências em cerca de 97% do tempo; mas não devemos deixar passar as oportunidades nos 3% críticos". O problema é saber quais são os 3%. Em quase todo programa lento, a maior parte do tempo é gasta numa fração pequena do código, e essa fração raramente é a que o programador imagina.

Daí a regra desta aula: medir antes de otimizar, e medir de novo depois. Primeiro, descobrir com dados onde está o custo. Depois, otimizar exatamente ali. Por fim, confirmar com dados que a otimização funcionou.

Um programa lento

Um gerador de relatório de vendas cria 2 milhões de vendas, formata cada uma como uma linha de texto e calcula o total por vendedor:

public class Relatorio {
    record Venda(String vendedor, String produto, double valor) { }

    static List<Venda> gerarVendas(int n) {
        String[] vendedores = {"Ana", "Bruno", "Carla", "Davi", "Eva"};
        String[] produtos = {"notebook", "mouse", "teclado", "monitor", "cabo"};
        List<Venda> vendas = new ArrayList<>();
        for (int i = 0; i < n; i++) {
            vendas.add(new Venda(vendedores[i % 5], produtos[(i * 7) % 5], (i % 1000) * 1.1));
        }
        return vendas;
    }

    static String formatarLinha(Venda v) {
        String texto = "";
        texto += v.vendedor();
        texto += ";";
        texto += v.produto();
        texto += ";";
        texto += String.format("%.2f", v.valor());
        return texto;
    }

    static Map<String, Double> totalPorVendedor(List<Venda> vendas) {
        Map<String, Double> totais = new TreeMap<>();
        for (Venda v : vendas) {
            totais.merge(v.vendedor(), v.valor(), Double::sum);
        }
        return totais;
    }

    public static void main(String[] args) {
        List<Venda> vendas = gerarVendas(2_000_000);
        long tamanho = 0;
        for (Venda v : vendas) {
            tamanho += formatarLinha(v).length();
        }
        IO.println("bytes de relatório: " + tamanho);
        IO.println(totalPorVendedor(vendas));
    }
}

Olhando o código, os suspeitos parecem óbvios: a concatenação com += em várias etapas, o TreeMap, o merge com autoboxing. Em vez de adivinhar, vamos gravar.

JDK Flight Recorder

O JFR (JDK Flight Recorder) é um gravador de eventos embutido na JVM, como a caixa-preta de um avião. Ele registra centenas de tipos de eventos: amostras de quais métodos estão executando, alocações de objetos, coletas de lixo, esperas por travas, leituras de arquivos e de rede, compilações do JIT. Foi projetado para rodar em produção: com as configurações padrão, o impacto no desempenho fica tipicamente abaixo de 1%. Uma gravação começa com uma opção na linha de comando:

java -XX:StartFlightRecording=filename=gravacao.jfr,settings=profile Relatorio

settings=profile usa uma configuração mais detalhada, adequada a investigações, e a configuração padrão (default) é a indicada para ficar ligada continuamente. Numa JVM que já está rodando, a gravação pode ser iniciada e gravada em arquivo com o jcmd da aula anterior: jcmd <pid> JFR.start e jcmd <pid> JFR.dump filename=agora.jfr. Não é preciso reiniciar o programa.

O arquivo .jfr pode ser analisado com a ferramenta jfr, que vem com o JDK. O comando jfr view mostra resumos prontos. Os métodos que mais executaram:

$ jfr view hot-methods gravacao.jfr

                           Java Methods that Execute the Most

Method                                                               Samples Percent
-------------------------------------------------------------------- ------- -------
java.util.Formatter.format(String, Object[])                              15  18.75%
java.lang.AbstractStringBuilder.needsNewBuffer(byte[], byte, int, byte)    5   6.25%
java.util.Formatter$FormatSpecifierParser.parsePrecision()                 5   6.25%
java.util.Formatter.format(Locale, String, Object[])                       4   5.00%
java.util.Formatter$FormatSpecifier.print(...)                             4   5.00%
java.util.Formatter.parse(String)                                          4   5.00%
java.lang.Double.valueOf(double)                                           3   3.75%
...
Relatorio.formatarLinha(Relatorio$Venda)                                   3   3.75%

E quem mais alocou memória:

$ jfr view allocation-by-class gravacao.jfr

Object Type                           Allocation Pressure
------------------------------------- -------------------
java.util.Formatter                               33.45%
byte[]                                            26.25%
java.lang.StringBuilder                           22.36%
Relatorio$Venda                                    5.89%

Os dados apontam um culpado que não estava na lista de suspeitos: o String.format. Cada chamada cria um objeto Formatter, interpreta o texto de formato "%.2f" do zero, converte o double para um objeto Double e só então formata. Métodos do Formatter somam quase metade das amostras de CPU, e os objetos Formatter são um terço de toda a memória alocada. O TreeMap e o merge, os suspeitos da intuição, nem aparecem.

A ferramenta também mostra as coletas de lixo:

$ jfr view gc gravacao.jfr

Start    GC ID Type                     Heap Before GC Heap After GC Longest Pause
-------- ----- ------------------------ -------------- ------------- -------------
10:08:22     1 Young Garbage Collection        57.3 MB       55.6 MB        103 ms
10:08:22     2 Young Garbage Collection        57.6 MB       58.6 MB       32.9 ms

E qualquer evento pode ser examinado em detalhe com jfr print --events <tipo>. jfr summary lista os tipos de evento gravados, e jfr help view lista todos os resumos disponíveis.

A correção guiada pelos dados

Com o culpado identificado, a correção é localizada: formatar o valor com duas casas sem String.format. Como o valor é positivo, basta trabalhar com centavos inteiros, a técnica de "Iguais ou o Mesmo?":

static String formatarLinhaRapido(Venda v) {
    long centavos = Math.round(v.valor() * 100);
    StringBuilder sb = new StringBuilder(32);
    sb.append(v.vendedor()).append(';').append(v.produto()).append(';')
      .append(centavos / 100).append('.');
    long resto = centavos % 100;
    if (resto < 10) {
        sb.append('0');
    }
    return sb.append(resto).toString();
}

Antes de medir a velocidade, o teste confere que as duas versões produzem exatamente o mesmo texto para as primeiras mil vendas. Uma otimização que muda o resultado não é uma otimização, é um defeito. Depois, a medição, com três rodadas de cada versão:

rodada 1: com format 819 ms, sem format 106 ms
rodada 2: com format 468 ms, sem format 66 ms
rodada 3: com format 411 ms, sem format 55 ms

Cerca de sete vezes mais rápido, numa única função, escolhida pelos dados. Essa versão tem limitações que a original não tinha: não trata valores negativos e ignora o idioma, sempre usando ponto como separador decimal. Numa situação real, essas limitações precisam ser aceitas conscientemente, ou tratadas. É a troca clássica entre desempenho e generalidade, e só vale a pena porque os dados mostraram que aquele ponto era o gargalo. Aplicada às 97% restantes do código, a mesma troca só traria complexidade.

JDK Mission Control

A ferramenta jfr responde perguntas específicas. Para explorar uma gravação livremente, existe o JDK Mission Control (JMC), um aplicativo gráfico gratuito, distribuído separadamente do JDK (por exemplo, pela Adoptium e pela Oracle). Ele abre um arquivo .jfr e mostra:

• uma página de resultados automáticos, que aplica dezenas de regras e aponta problemas prováveis, como alocação excessiva, esperas longas por travas ou muitas exceções lançadas;
• as amostras de métodos em forma de árvore de chamadas e de flame graph, um gráfico em que a largura de cada bloco mostra quanto tempo foi gasto num método e em tudo o que ele chamou;
• linhas do tempo das threads, das coletas de lixo, do uso de memória e de CPU;
• os eventos de entrada e saída, com a duração de cada leitura de arquivo e cada chamada de rede.

Para o dia a dia, a combinação mais útil é deixar o JFR gravando continuamente em produção, com a configuração padrão e um limite de tamanho ou de tempo (maxage=1h, por exemplo), e salvar a gravação quando algo estranho acontecer. É como ter a caixa-preta disponível logo depois do acidente. O JFR tem evoluído a cada versão: o Java 25, por exemplo, acrescentou uma forma de medir o tempo e registrar as chamadas de métodos específicos, e, no Linux, um modo experimental de amostragem pelo tempo real de CPU.

Medir um trecho de código: por que é difícil

O JFR mostra onde um programa gasta tempo. Mas às vezes a pergunta é outra: entre duas implementações de um método, qual é mais rápida? A resposta parece fácil: medir com System.nanoTime() antes e depois, como a comparação acima. E essa é justamente a forma mais comum de chegar a conclusões erradas. Um exemplo:

for (int rodada = 1; rodada <= 3; rodada++) {
    long t0 = System.nanoTime();
    for (int i = 0; i < 100_000_000; i++) {
        Math.sqrt(i);                       // resultado descartado
    }
    long t1 = System.nanoTime();
    double soma = 0;
    for (int i = 0; i < 100_000_000; i++) {
        soma += Math.sqrt(i);               // resultado usado
    }
    long t2 = System.nanoTime();
    IO.println("rodada " + rodada + ": resultado descartado " + (t1 - t0) / 1_000_000
               + " ms, resultado usado " + (t2 - t1) / 1_000_000 + " ms (" + (long) soma + ")");
}

rodada 1: resultado descartado 2 ms, resultado usado 221 ms
rodada 2: resultado descartado 8 ms, resultado usado 211 ms
rodada 3: resultado descartado 0 ms, resultado usado 218 ms

Calcular 100 milhões de raízes quadradas em zero milissegundos é impossível. O JIT percebeu que o resultado de Math.sqrt no primeiro laço nunca é usado, e que a função não tem efeitos colaterais, e eliminou o cálculo, e depois o laço vazio. É a eliminação de código morto, uma otimização legítima, que destrói a medição. Um benchmark ingênuo concluiria que Math.sqrt é cem vezes mais rápido do que é.

Esse é só um dos problemas. Os principais:

• Aquecimento. Como vimos em "A Máquina por Trás da Máquina", as primeiras execuções são interpretadas e as seguintes são compiladas pelo C1 e depois pelo C2. Medir sem aquecer mede o interpretador.
• Eliminação de código morto, como acima.
• Constantes dobradas. Se os valores de entrada são constantes conhecidas, o JIT pode calcular o resultado uma vez e reaproveitá-lo.
• Perfil contaminado. Medir duas implementações no mesmo processo, uma depois da outra, faz o JIT otimizar a segunda com o perfil gerado pela primeira. A ordem das medições muda os resultados.
• Ruído. Coletas de lixo, outros programas, o sistema operacional e a variação de frequência do processador mudam os tempos de uma execução para outra. Uma única medição não diz nada.

JMH: o jeito certo

O JMH (Java Microbenchmark Harness) é a ferramenta criada pela própria equipe do OpenJDK para medir código Java corretamente. Ele cuida de todos os problemas acima: aquece o código, repete as medições muitas vezes, roda cada benchmark em processos separados da JVM e calcula as estatísticas. A forma mais simples de começar é gerar um projeto Maven a partir do modelo oficial:

mvn archetype:generate -DarchetypeGroupId=org.openjdk.jmh \
    -DarchetypeArtifactId=jmh-java-benchmark-archetype \
    -DgroupId=br.com.exemplo -DartifactId=benchmarks

Um benchmark comparando as duas formatações:

package br.com.exemplo;

import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.infra.Blackhole;

import java.util.concurrent.TimeUnit;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 5, time = 1)
@Measurement(iterations = 10, time = 1)
@Fork(2)
@State(Scope.Benchmark)
public class FormatacaoBenchmark {

    private double valor;

    @Setup
    public void preparar() {
        valor = 1234.5;
    }

    @Benchmark
    public String comFormat() {
        return String.format("%.2f", valor);
    }

    @Benchmark
    public void semFormat(Blackhole bh) {
        long centavos = Math.round(valor * 100);
        bh.consume(centavos / 100 + "." + (centavos % 100 < 10 ? "0" : "") + (centavos % 100));
    }
}

As anotações, lidas pelo JMH por meio de um processador de anotações, a técnica mencionada em "O Programa que se Examina", configuram a medição:

• @Benchmark marca cada método a medir.
• @BenchmarkMode(Mode.AverageTime) mede o tempo médio por operação. Outros modos medem a vazão (operações por segundo) ou a distribuição dos tempos.
• @Warmup e @Measurement definem quantas rodadas de aquecimento são descartadas, e quantas de medição são registradas.
• @Fork(2) roda cada benchmark em dois processos novos da JVM, para que um benchmark não contamine o perfil do outro.
• @State e @Setup preparam os dados fora da medição. O valor vem de um campo, e não de uma constante no código, para que o JIT não possa dobrá-lo.
• Devolver o resultado, ou passá-lo a um Blackhole, impede a eliminação de código morto: o JMH "consome" o valor de um jeito que o JIT não consegue provar que é inútil.

Depois de mvn package, o benchmark roda com java -jar target/benchmarks.jar. A saída termina com uma tabela neste formato (os números abaixo são ilustrativos, e os seus dependem da máquina):

Benchmark                         Mode  Cnt    Score    Error  Units
FormatacaoBenchmark.comFormat     avgt   20  230.512 ±  4.101  ns/op
FormatacaoBenchmark.semFormat     avgt   20   24.873 ±  0.512  ns/op

Score é o tempo médio por operação, e Error é a margem de erro. Se as margens de dois resultados se sobrepõem, a diferença entre eles não é confiável. Uma otimização que ganha 2% com uma margem de 5% não ganhou nada que se possa afirmar.

Dois avisos finais. Primeiro, um microbenchmark mede um trecho de código isolado. O mesmo trecho, dentro do programa real, pode se comportar de outra forma, porque o perfil e a memória são outros. O JMH responde "qual das duas implementações é mais rápida", e o JFR responde "isso importa para o meu programa". Segundo, o próprio JMH não impede todos os erros. Os exemplos oficiais do projeto, dezenas de benchmarks comentados que mostram as armadilhas uma por uma, são leitura obrigatória antes de confiar nos seus números.

As ferramentas desta aula valem para qualquer código que rode na JVM. Mas nem todo código útil é escrito em Java: as bibliotecas do sistema operacional, de criptografia, de compressão e de aprendizado de máquina são, em grande parte, escritas em C e C++, e às vezes o caminho mais rápido, medido e não adivinhado, é usar o que já existe.

Fontes e leituras recomendadas

• Oracle, "JDK Flight Recorder" (Java SE 25, guia de solução de problemas): https://docs.oracle.com/en/java/javase/25/troubleshoot/diagnostic-tools.html. O uso do JFR pela linha de comando e pelo jcmd, e a ferramenta jfr.
• JDK Mission Control: https://jdk.java.net/jmc/. A página oficial com os downloads e a documentação do JMC.
• OpenJDK, "JMH Samples": https://github.com/openjdk/jmh/tree/master/jmh-samples/src/main/java/org/openjdk/jmh/samples. Os exemplos oficiais do JMH, cada um explicando uma armadilha de medição com comentários detalhados.
• Donald Knuth, "Structured Programming with go to Statements" (1974): https://dl.acm.org/doi/10.1145/356635.356640. O artigo em que aparece a frase sobre a otimização prematura, no contexto completo.
• Brendan Gregg, "Flame Graphs": https://www.brendangregg.com/flamegraphs.html. O criador dos flame graphs explica como lê-los. A visualização é usada pelo JMC e por várias outras ferramentas de análise de desempenho.

Exercícios

Exercício 1

No relatório de vendas, um colega propôs trocar o TreeMap por um HashMap e a concatenação com += por um StringBuilder, para acelerar o programa. Com base na gravação do JFR, avalie a proposta.

Exercício 2

Explique por que o primeiro laço do exemplo ingênuo "levou" 0 ms, e mostre duas formas de impedir essa distorção numa medição manual.

Exercício 3

Um serviço em produção fica lento algumas vezes por dia, por alguns minutos, sem padrão aparente. Descreva como o JFR ajudaria a investigar, sem reiniciar o serviço.

Exercício 4

Para cada anotação ou recurso do JMH, diga qual armadilha de medição ele evita: @Warmup, @Fork, @Setup com os dados num campo, Blackhole (ou devolver o resultado), e a repetição com @Measurement e o cálculo do erro.

Exercício 5

A versão rápida de formatarLinha foi sete vezes mais rápida que a original. Liste o que ela perdeu em relação à original, e diga em que condições você aceitaria essa troca no código de um sistema real.