Medir el rendimiento en Java sin engañarse

Medir en la JVM es más difícil que en casi cualquier otro sitio, porque el código se va optimizando mientras corre. Esta página enseña el error con números reales, y cómo evitarlo.

También te puede interesar

La medición ingenua

long medir(Runnable r) {
    long t0 = System.nanoTime();
    r.run();
    return (System.nanoTime() - t0) / 1000;    // microsegundos
}

Concatenando 200 trozos de texto, de las dos formas conocidas:

salidaconcatenar con + : 450 µs
  StringBuilder    : 70 µs

Conclusión aparente: el StringBuilder es seis veces más rápido. Es verdad que es más rápido, pero ese «seis veces» no significa nada. Mira qué pasa al repetir exactamente lo mismo:

salidavuelta 1: +=254 µs   builder=27 µs
  vuelta 2: +=102 µs   builder=44 µs
  vuelta 3: +=60 µs    builder=26 µs
  vuelta 4: +=70 µs    builder=20 µs
  vuelta 5: +=77 µs    builder=21 µs

El mismo código, con los mismos datos, pasa de 254 a 60 µs sin que nadie toque nada.

Lo que está pasando

La JVM empieza interpretando el bytecode. Según ve que un método se usa mucho, el compilador JIT lo traduce a código nativo, y luego lo vuelve a optimizar con lo que ha aprendido: qué ramas se toman, qué tipos aparecen de verdad, qué se puede incorporar en línea. Ese proceso tarda unos cuantos miles de ejecuciones.

Así que una medición tomada en frío mide el intérprete y el propio compilador, no tu código. Con veinte mil vueltas de calentamiento antes de medir:

salidaconcatenar con + : 20 µs
  StringBuilder    : 5 µs
  Builder + Grow   : 42 µs
  String.join      : 104 µs

Ahora el += baja de 70 a 20 µs. Pero fíjate en las dos últimas líneas: Grow y String.join, que deberían ser las más rápidas, salen las peores. ¿Están mal implementadas?

No. Es que solo calenté las dos primeras. Calentando también las otras dos, sin cambiar una línea del código medido:

salidaBuilder + Grow   : 4 µs
  String.join      : 3 µs
De 104 a 3 microsegundos por haber ejecutado la función antes. Es treinta veces, y el código es idéntico. Si hubiera publicado la tabla anterior como resultado, habría dicho que String.join es veinte veces más lento que un StringBuilder, que es exactamente lo contrario de la verdad.

Las otras trampas

  • Eliminación de código muerto. Si no usas el resultado, el JIT puede descubrir que la llamada no hace nada observable y borrarla entera. Entonces mides un bucle vacío.
  • Plegado de constantes. Si la entrada es una constante, el compilador puede calcular el resultado una vez y reutilizarlo.
  • El recolector de basura. Puede entrar en mitad de la medición y cargarle a tu código un tiempo que no es suyo.
  • System.currentTimeMillis() no sirve para medir: su resolución puede ser de milisegundos enteros y, peor, puede saltar hacia atrás si el reloj se sincroniza. Para medir intervalos, siempre System.nanoTime().

Cómo se hace de verdad: JMH

La herramienta oficial es JMH, del propio equipo de OpenJDK. Se encarga del calentamiento, de aislar las medidas en procesos nuevos, de impedir la eliminación de código muerto y de dar intervalos de confianza:

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

    List<String> piezas;

    @Setup public void preparar() { piezas = ...; }

    @Benchmark public String conBuilder() {
        var b = new StringBuilder();
        for (String p : piezas) b.append(p);
        return b.toString();                      // devolverlo evita que lo borren
    }
}
mvn archetype:generate -DinteractiveMode=false \
    -DarchetypeGroupId=org.openjdk.jmh -DarchetypeArtifactId=jmh-java-benchmark-archetype

mvn clean package && java -jar target/benchmarks.jar

Lo importante no son las anotaciones, es lo que implican: @Warmup antes de medir, @Fork(2) para repetir en dos procesos distintos —porque el estado del JIT de una ejecución contamina la siguiente— y devolver el resultado desde el método, que es lo que impide que lo eliminen.

Y la memoria

Runtime rt = Runtime.getRuntime();
System.gc();
long antes = rt.totalMemory() - rt.freeMemory();
// … hacer el trabajo, guardando los resultados para que no los recoja el GC …
long despues = rt.totalMemory() - rt.freeMemory();
salida200 concatenaciones con + : 40 MB vivos

Esa cifra sirve para ver un orden de magnitud y poco más: System.gc() es una sugerencia que la JVM puede ignorar, y la medida varía bastante entre ejecuciones —en otra pasada me dio 9 MB—. Para memoria de verdad, -prof gc de JMH, o un perfilador como async-profiler.

Para… Usa
Medir un intervalo System.nanoTime(), nunca currentTimeMillis
Una idea rápida calentar unas miles de vueltas y repetir la medida
Comparar dos implementaciones JMH, sin excepción
Que no borren el código medido devolver el resultado desde el método
Saber dónde se va el tiempo un perfilador, no un cronómetro

Todo el código se compiló y se ejecutó con Java 25 LTS en un contenedor limpio antes de publicar esta página; las salidas están copiadas de esa ejecución.