Benchmark com JMH: por que o loop com System.nanoTime mede errado

Quase toda discussão de performance em Java começa do mesmo jeito. Alguém coloca dois System.nanoTime() em volta de um trecho, roda um loop de dez milhões de voltas, faz a divisão e cola o número no pull request. Ninguém pergunta o que o JIT fez com aquele loop enquanto o relógio corria.

Não é má-fé. A JVM otimiza o código enquanto você mede, e três coisas acontecem ao mesmo tempo. O warmup contamina as primeiras voltas. O código cujo resultado ninguém lê desaparece. Uma conta constante vira um valor pronto. O loop cronometrado mistura tudo isso num número só.

Aqui você vai ver os três efeitos num loop ingênuo, montar a medição certa com JMH num projeto Maven no Java 25, ler Score e Error sem se enganar e saber quando o JMH é o instrumento errado.

O ambiente da medição

Tudo rodou em 25 de setembro de 2026, numa VM compartilhada com 4 vCPUs (AMD EPYC-Rome Processor, primeiro core reportando 2445.406 MHz) e 7.6 GiB de RAM, com Ubuntu 26.04 LTS e kernel 7.0.0-27-generic. Versões: Temurin 25.0.4+7 LTS, Maven 3.9.12 e JMH 1.37.

O Java 25 é a LTS atual segundo o roadmap de suporte da Oracle, com GA em 16 de setembro de 2025 (página do JDK 25 no OpenJDK). Pelos metadados do Maven Central, 1.37 é a release mais recente do JMH.

Os números valem para esta máquina, neste dia. Não servem para estimar a capacidade de nada em produção.

O loop com System.nanoTime, do jeito que todo mundo escreve

O programa tem três colunas, cada uma com 10 milhões de iterações e 6 repetições. Não tem warmup, não tem fork e não tem Blackhole:

package academy.devdojo.jmh;

import java.util.Locale;

/**
 * The naive microbenchmark: System.nanoTime() around a hot loop, no warmup,
 * no forking, no blackhole. Run it three times and compare with the JMH run.
 *
 * Columns:
 *   dead_ns_op      -> result of the hot path is never used (dead code candidate)
 *   foldable_ns_op  -> loop-invariant add, result used (constant folding candidate)
 *   used_ns_op      -> loop-variant add, result used (the only "honest" column)
 *   ops_per_ns      -> throughput implied by the column; > ~4 ops/ns is physically
 *                      impossible on a single core, so the number is an artifact
 */
public class NaiveNanoTime {

    private static final int ITERATIONS = 10_000_000;
    private static final int REPS = 6;

    static long hotPath(long x) {
        return x * 31 + 7;
    }

    public static void main(String[] args) {
        System.out.println("naive-nanotime iterations=" + ITERATIONS + " reps=" + REPS
                + " jvm=" + System.getProperty("java.vm.version"));
        System.out.println("rep,dead_ns_op,dead_ops_per_ns,foldable_ns_op,foldable_ops_per_ns,used_ns_op,used_ops_per_ns");

        for (int rep = 1; rep <= REPS; rep++) {
            // A) result discarded: the compiler is free to delete the whole loop
            long t0 = System.nanoTime();
            for (int i = 0; i < ITERATIONS; i++) {
                long ignored = hotPath(i);
            }
            long t1 = System.nanoTime();
            double dead = (t1 - t0) / (double) ITERATIONS;

            // B) loop-invariant computation with a used result: constant folding candidate
            long t2 = System.nanoTime();
            long folded = 0;
            for (int i = 0; i < ITERATIONS; i++) {
                folded += 3 * 4;
            }
            long t3 = System.nanoTime();
            double foldable = (t3 - t2) / (double) ITERATIONS;

            // C) loop-variant computation with a used result
            long t4 = System.nanoTime();
            long sum = 0;
            for (int i = 0; i < ITERATIONS; i++) {
                sum += hotPath(i);
            }
            long t5 = System.nanoTime();
            double used = (t5 - t4) / (double) ITERATIONS;

            System.out.printf(Locale.ROOT, "%d,%.6f,%.3f,%.6f,%.3f,%.6f,%.3f%n",
                    rep, dead, opsPerNs(dead), foldable, opsPerNs(foldable), used, opsPerNs(used));

            if (folded == Long.MIN_VALUE || sum == Long.MIN_VALUE) {
                System.out.println("unreachable sink " + folded + " " + sum);
            }
        }
    }

    private static double opsPerNs(double nsPerOp) {
        return nsPerOp <= 0.0 ? Double.POSITIVE_INFINITY : 1.0 / nsPerOp;
    }
}

Ele rodou três vezes, cada vez numa JVM nova, com java -cp target/classes academy.devdojo.jmh.NaiveNanoTime. Esta é a primeira execução:

naive-nanotime iterations=10000000 reps=6 jvm=25.0.4+7-LTS
rep,dead_ns_op,dead_ops_per_ns,foldable_ns_op,foldable_ops_per_ns,used_ns_op,used_ops_per_ns
1,0.778754,1.284,0.305308,3.275,1.004656,0.995
2,1.152258,0.868,0.000003,333333.333,0.338771,2.952
3,0.000003,322580.645,0.000003,333333.333,0.338985,2.950
4,0.000003,333333.333,0.000003,333333.333,0.339685,2.944
5,0.000003,344827.586,0.000003,322580.645,0.333577,2.998
6,0.000005,196078.431,0.000003,333333.333,0.335848,2.978

A tabela mostra três erros diferentes.

Warmup ignorado. Na coluna used, a repetição 1 marcou 1.004656 ns/op e a 6 marcou 0.335848. A primeira volta foi 2,99× mais lenta que a última. As outras duas JVMs repetiram o padrão (1.058541 → 0.337724 e 1.002936 → 0.341853). Quem mede uma vez só, com a JVM fria, está medindo a JVM esquentando, não o método.

Código morto eliminado. Na coluna dead, as repetições 1 e 2 marcaram 0.778754 e 1.152258. Da 3 em diante, o valor fica entre 0.000003 e 0.000005 ns/op. O código não mudou: ninguém lê ignored, e o JIT percebeu isso antes de qualquer revisor e removeu o loop.

Constante dobrada. Na coluna foldable, a repetição 1 marcou 0.305308 ns/op e, a partir da 2, 0.000003. O mesmo formato apareceu nas três JVMs. Somar 3 * 4 dez milhões de vezes dá um resultado que se calcula sem rodar o loop, e o JIT fez exatamente isso.

A própria saída acusa o problema. A coluna ops_per_ns imprime 333333.333 operações por nanossegundo. Mesmo sendo generoso com o clock registrado deste host (na casa de 2,4 GHz) e supondo 4 instruções por ciclo, um core fica na ordem de 10 operações por nanossegundo. O valor colapsado está umas quatro ordens de grandeza além do hardware. O 0.000003 não é uma taxa. É a resolução do relógio dividida por 10 milhões, ou seja, a região cronometrada inteira levou uns 30 ns. Nessa hora o benchmark está medindo o relógio da máquina. Serve de teste rápido: se o número por operação implica mais que algumas operações por nanossegundo, ele veio do instrumento, não do código.

Montando o projeto Maven com JMH no Java 25

O projeto tem o pom.xml na raiz e os fontes em src/main/java/academy/devdojo/jmh/ (NaiveNanoTime.java e HotPathBenchmark.java).

O JMH gera o código do harness a partir das suas anotações, em tempo de compilação, com um annotation processor. Por isso o pom.xml precisa de mais do que uma dependência:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>

  <groupId>academy.devdojo.jmh</groupId>
  <artifactId>jmh-benchmark</artifactId>
  <version>1.0-SNAPSHOT</version>
  <packaging>jar</packaging>
  <name>devdojo-jmh-benchmark</name>

  <properties>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    <maven.compiler.release>25</maven.compiler.release>
    <jmh.version>1.37</jmh.version>
  </properties>

  <dependencies>
    <dependency>
      <groupId>org.openjdk.jmh</groupId>
      <artifactId>jmh-core</artifactId>
      <version>${jmh.version}</version>
    </dependency>
    <dependency>
      <groupId>org.openjdk.jmh</groupId>
      <artifactId>jmh-generator-annprocess</artifactId>
      <version>${jmh.version}</version>
      <scope>provided</scope>
    </dependency>
  </dependencies>

  <build>
    <finalName>benchmarks</finalName>
    <plugins>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-compiler-plugin</artifactId>
        <version>3.14.0</version>
        <configuration>
          <release>25</release>
          <!-- explicit processor path: annotation processing is NOT auto-discovered
               from the compile classpath on modern JDKs / plugin versions -->
          <annotationProcessorPaths>
            <path>
              <groupId>org.openjdk.jmh</groupId>
              <artifactId>jmh-generator-annprocess</artifactId>
              <version>${jmh.version}</version>
            </path>
          </annotationProcessorPaths>
        </configuration>
      </plugin>

      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-shade-plugin</artifactId>
        <version>3.6.1</version>
        <executions>
          <execution>
            <phase>package</phase>
            <goals><goal>shade</goal></goals>
            <configuration>
              <transformers>
                <transformer implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
                  <mainClass>org.openjdk.jmh.Main</mainClass>
                </transformer>
              </transformers>
              <filters>
                <filter>
                  <artifact>*:*</artifact>
                  <excludes>
                    <exclude>META-INF/*.SF</exclude>
                    <exclude>META-INF/*.DSA</exclude>
                    <exclude>META-INF/*.RSA</exclude>
                  </excludes>
                </filter>
              </filters>
            </configuration>
          </execution>
        </executions>
      </plugin>
    </plugins>
  </build>
</project>

O maven-shade-plugin gera target/benchmarks.jar com org.openjdk.jmh.Main como classe principal. Ele também escreve um dependency-reduced-pom.xml na raiz do projeto, o que é esperado.

O bloco que mais importa é o <annotationProcessorPaths>. Num projeto de controle com o mesmo POM, só que sem esse bloco, o Maven compila, empacota e responde com sucesso. O erro só aparece quando você tenta rodar:

[INFO] BUILD SUCCESS
MVN_EXIT=0
Exception in thread "main" java.lang.RuntimeException: ERROR: Unable to find the resource: /META-INF/BenchmarkList
	at org.openjdk.jmh.runner.AbstractResourceReader.getReaders(AbstractResourceReader.java:98)
	at org.openjdk.jmh.runner.BenchmarkList.find(BenchmarkList.java:124)
	at org.openjdk.jmh.runner.Runner.internalRun(Runner.java:252)
	at org.openjdk.jmh.runner.Runner.run(Runner.java:208)
	at org.openjdk.jmh.Main.main(Main.java:71)
JAVA_EXIT=1

O build passa e o jar não roda. O que separa um build verde de um jar executável são estes dois comandos, depois do package:

jar tf target/benchmarks.jar | grep META-INF/BenchmarkList
find target/generated-sources -name "*jmh*"

O primeiro precisa listar META-INF/BenchmarkList. O segundo precisa encontrar as classes geradas em target/generated-sources/annotations/academy/devdojo/jmh/jmh_generated/. Se algum dos dois voltar vazio, o annotation processor não rodou.

Esta é a classe de benchmark, exatamente como foi executada:

package academy.devdojo.jmh;

import java.util.concurrent.TimeUnit;

import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Threads;
import org.openjdk.jmh.annotations.Warmup;
import org.openjdk.jmh.infra.Blackhole;

/**
 * Three benchmarks, three lessons:
 *
 *  sumLoop                        -> the measured hot path, consumed through Blackhole,
 *                                    thread-local state (the correct instrument)
 *  counterThreadScope             -> same mutable field increment, @State(Scope.Thread)
 *  counterBenchmarkScope          -> same mutable field increment, @State(Scope.Benchmark)
 *
 * The last two differ only in State scope: the second writes to a field shared by all
 * four threads, so the measured cost is cache-line contention, not the code.
 */
@BenchmarkMode(Mode.Throughput)
@OutputTimeUnit(TimeUnit.SECONDS)
@Warmup(iterations = 3, time = 1)
@Measurement(iterations = 5, time = 1)
@Fork(2)
public class HotPathBenchmark {

    private static final int LOOPS = 10_000;

    @State(Scope.Thread)
    public static class ThreadLocalState {
        long acc;          // one instance per thread: no sharing
    }

    @State(Scope.Benchmark)
    public static class SharedState {
        long shared;       // one instance for the whole run: every thread writes here
    }

    @Benchmark
    public void sumLoop(ThreadLocalState state, Blackhole blackhole) {
        long local = state.acc;
        for (int i = 0; i < LOOPS; i++) {
            local = local * 31 + 7;
        }
        state.acc = local;
        blackhole.consume(local);       // without this, the JIT may delete the loop
    }

    @Benchmark
    @Threads(4)
    public void counterThreadScope(ThreadLocalState state, Blackhole blackhole) {
        for (int i = 0; i < LOOPS; i++) {
            state.acc++;
        }
        blackhole.consume(state.acc);
    }

    @Benchmark
    @Threads(4)
    public void counterBenchmarkScope(SharedState state, Blackhole blackhole) {
        for (int i = 0; i < LOOPS; i++) {
            state.shared++;
        }
        blackhole.consume(state.shared);
    }
}

Cada anotação responde a um dos erros do loop ingênuo:

Para compilar e rodar:

mvn -q -DskipTests package
java -jar target/benchmarks.jar -l
java -jar target/benchmarks.jar

Rode sempre pelo jar, não pela IDE: o README do JMH diz que, na IDE, a configuração é "more complex and the results are less reliable".

O build a frio levou 13.2 s, contando downloads. O -l lista os três benchmarks. A execução completa terminou com # Run complete. Total time: 00:00:49, cerca de 50 s de relógio de parede. O cabeçalho confirma a configuração: # Warmup: 3 iterations, 1 s each, # Measurement: 5 iterations, 1 s each e # Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable).

No JDK 25, cada fork imprime um WARNING avisando que sun.misc.Unsafe::objectFieldOffset foi chamado por org.openjdk.jmh.util.Utils. O aviso vem do código interno do JMH e não indica incompatibilidade com o Java 25.

Três armadilhas que o JMH não resolve sozinho

Loop unrolling dentro do benchmark

O JMH não impede que você escreva um loop dentro do @Benchmark. O JMHSample_11_Loops, nos samples oficiais, avisa: "you will see there is more magic happening when we allow optimizers to merge the loop iterations". As colunas dead e foldable do loop ingênuo mostram essa mágica levada ao extremo.

O sumLoop tem um loop de 10.000 voltas de propósito. Cada volta depende da anterior e o resultado é consumido. Mesmo assim, o Score conta chamadas do método, não voltas do loop. Dividir por 10.000 para chegar ao custo de uma volta pressupõe que você sabe o que o JIT fez com o loop. Também não compare o sumLoop com a coluna used do loop ingênuo: sum += hotPath(i) e local = local * 31 + 7 são recorrências diferentes.

Se a pergunta é o custo de uma volta, tire o loop de dentro do @Benchmark e deixe o JMH repetir a chamada. Se o loop precisa ficar, declare @OperationsPerInvocation(10_000) no método: com ela, o Score passa a contar voltas do loop, não chamadas.

Estado compartilhado entre threads

counterThreadScope e counterBenchmarkScope executam o mesmo incremento com @Threads(4). A única diferença é quem é dono do campo:

A diferença é de 10,43×. O segundo número não mede o incremento. Ele mede quatro cores disputando a mesma linha de cache (veja também o JMHSample_22_FalseSharing). Esse fator pertence a esta configuração: 4 threads incrementando um long em 4 vCPUs compartilhadas. Guarde o estado mutável em Scope.Thread, a não ser que a contenção seja justamente a pergunta.

Resultado que só existe no seu laptop

No benchmark com contenção, as médias dos dois forks ficaram em 135.617.169 e 159.710.711 ops/s, uma distância de 16,32%. Nos benchmarks sem disputa, os forks concordam em 0,51% (sumLoop) e 0,06% (counterThreadScope). Com um fork só, um "20% mais rápido" pode ser pura sorte na inicialização da JVM, que é o assunto do JMHSample_12_Forking e do JMHSample_13_RunToRun. Por isso use pelo menos dois forks e nunca @Fork(0). Também só compare execuções com a mesma JVM, o mesmo hardware e o mesmo modo de Blackhole: a nota final do JMH avisa que a diferença entre modos "can be very significant".

Lendo a saída: Score, Error e ops/s

A tabela final, como o JMH imprimiu:

Benchmark                                Mode  Cnt           Score          Error  Units
HotPathBenchmark.counterBenchmarkScope  thrpt   10   147663940.288 ± 19890606.627  ops/s
HotPathBenchmark.counterThreadScope     thrpt   10  1540289479.933 ± 15442130.687  ops/s
HotPathBenchmark.sumLoop                thrpt   10      152219.898 ±     1245.595  ops/s

• Mode e Units: thrpt em ops/s, então maior é melhor. Em ns/op, menor seria melhor. Sempre diga o modo junto com o número.
• Cnt: 10 são 5 iterações de medição × 2 forks. É a quantidade de amostras por trás do Score.
• Score: a média de todas as iterações medidas, somando os forks.
• Error: metade da largura do intervalo de confiança de 99,9%. O JMH também imprime (min, avg, max), stdev e o intervalo inteiro. No benchmark com contenção, o intervalo é CI (99.9%): [127773333.661, 167554546.916], uma faixa de 27% em termos relativos.

O Error representa 13,47% do Score no benchmark com contenção, 1,00% no counterThreadScope e 0,82% no sumLoop. Daí sai a regra prática: uma diferença só conta quando os intervalos das duas variantes não se sobrepõem, ou seja, nesta configuração, quando ela passa da soma dos dois Error. No sumLoop, com uns 0,82% de cada lado, isso dá um piso prático de uns 1,6% para esta configuração. No benchmark com contenção, um "ganho" de 5% ou 10% ainda está dentro da barra de erro.

O Error depende da configuração. Um smoke run com -wi 1 -i 1 -f 1 imprimiu 150487.920 ops/s com a coluna Error vazia. Aquilo é uma amostra, não um resultado. O loop ingênuo devolve seis casas decimais e nenhuma barra de erro, e mesmo assim o número vai parar no pull request.

O próprio JMH encerra a execução dizendo que os números "are just data" e pede: "Do not assume the numbers tell you what you want them to tell." Para entender por que um número saiu daquele jeito, use os profilers do harness (-lprof lista os disponíveis). Esta rodada não coletou dados de profiler.

Quando o JMH é o instrumento errado

Em Mode.Throughput, o ops/s mede um trecho quente que roda dentro do processo. O README diz que o JMH cobre "nano/micro/milli/macro benchmarks", então ele roda código que faz I/O sem problema. O problema é outro: quando a resposta depende de disco, socket, pool de conexões ou serviço remoto, o numerador deixa de medir trabalho de CPU e passa a medir o outro sistema. E antes de escrever qualquer benchmark, confirme com JFR ou async-profiler que o trecho é mesmo quente.

Para chamadas de rede, testes de integração e acesso a banco, a pergunta costuma ser sobre latência sob concorrência. Aí o instrumento é outro: percentis p50/p95/p99 medidos de ponta a ponta, com um gerador de carga, timeouts, retries e backpressure realistas. Em produção, esses percentis saem das métricas p95/p99 do próprio serviço ou da stack de APM do time. O artigo sobre Reactor, virtual threads e paralelismo no Spring Boot mediu latência de ponta a ponta, CPU e fila do pipeline inteiro. Um benchmark JMH de um método daquele pipeline responderia a outra pergunta.

A recomendação

Coloque as duas variantes como @Benchmark na mesma classe, com pelo menos dois forks, estado mutável em Scope.Thread e resultado consumido. Rode na mesma JVM e no mesmo hardware e reporte Score ± Error com a unidade.

Como próximo passo, copie o projeto, troque o sumLoop pelo seu trecho quente, adicione a variante como um segundo @Benchmark e rode java -jar target/benchmarks.jar. Só abra o PR se a diferença contar: os intervalos das duas variantes não se sobrepõem, ou seja, ela passa da soma dos dois Error.