May 29, 2021

all posts ->

A veces, tu aplicación funciona, pero deseas aumentar su rendimiento aumentando su rendimiento o reduciendo su latencia. Otras veces, solo quieres saber cómo se comporta el código en tiempo de ejecución, determinar dónde están los puntos críticos, o averiguar cómo opera un framework bajo el capó.

Este es un caso de uso perfecto para los perfiles. Ofrecen una vista de pájaro de bloques de ejecución arbitrariamente grandes, lo que te ayuda a ver problemas a gran escala.

Mucha gente cree que no necesitan aprender a perfilar siempre y cuando no escriban aplicaciones de alta carga. En el ejemplo, veremos cómo podemos beneficiarnos del perfilado incluso cuando tratamos con aplicaciones muy simples.

Aplicación de ejemplo

Digamos que tenemos el siguiente programa:

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.*;
import java.util.concurrent.TimeUnit;

public class CountEvents {

    public static int update(Deque<Long> events, long nanos, long interval) {
        events.add(nanos);
        events.removeIf(aTime -> aTime < nanos - interval);
        return events.size();
    }

    public static void main(String[] args) throws IOException {
        long start = System.nanoTime();
        int total = 100_000;
        long interval = TimeUnit.MILLISECONDS.toNanos(100);
        int[] count = new int[total];

        Deque<Long> collection = new ArrayDeque<>();
        for (int counter = 0; counter < count.length; counter++) {
            count[counter] = update(collection, System.nanoTime(), interval);
            Path p = Paths.get("./a/b");
            Files.createDirectories(p);
        }
        long spent = System.nanoTime() - start;

        //noinspection OptionalGetWithoutIsPresent
        System.out.println("Average count: " + (int) (Arrays.stream(count).average().getAsDouble()) + " op");
        System.out.println("Spent time: " + TimeUnit.NANOSECONDS.toMillis(spent) + " ms");
    }
}

El programa intenta de manera repetida crear una ruta en el sistema de archivos usando createDirectories() de NIO2. Luego medimos el rendimiento utilizando una prueba de referencia improvisada.

Cada vez que se ejecuta una tarea, la lógica de la prueba de referencia almacena la marca de tiempo actual en una colección y elimina todas las marcas de tiempo que apuntan a un tiempo anterior al tiempo actual menos algún intervalo. Esto hace posible averiguar cuántos eventos ocurrieron durante este intervalo de tiempo simplemente consultando la colección. Se supone que esta prueba de referencia nos ayudará a evaluar el rendimiento del método createDirectories() .

Cuando ejecutamos el programa, encontramos que las cifras son sospechosamente bajas:

Average count: 6623 op
Spent time: 1462 ms

Vamos a perfilarlo y ver qué está mal.

Obtén una instantánea

Primero, necesitamos recolectar datos de perfilado, a lo que también se le conoce como instantánea. En esta etapa, el perfil se ejecuta junto con el programa recolectando información sobre su actividad. Los perfiles usan diferentes técnicas para lograr esto, como la instrumentación de entradas y salidas de métodos. El Profiler de IntelliJ lo hace recogiendo periódicamente la información de pila de todos los hilos que se ejecutan en la aplicación.

Para adjuntar el perfil desde IntelliJ IDEA, elige una configuración de ejecución que normalmente usarías para ejecutar la aplicación, y selecciona Profile en el menú.

Cuando la aplicación ha terminado de ejecutarse, aparecerá una ventana emergente, instándonos a abrir la instantánea. Si descartamos la ventana emergente por error, la instantánea seguirá estando disponible en la ventana de herramientas Profiler.

Abramos el informe y veamos qué contiene.

Analiza la instantánea

Lo primero que vemos después de abrir el informe es el gráfico de llama. Esto es esencialmente un resumen de todas las pilas muestreadas. Cuanto más muestras con la misma pila haya recogido el perfilador, más crecerá esta pila en el gráfico de llamas. Así, el ancho del marco se asemeja aproximadamente a la porción del tiempo dedicado a este estado.

¡Para nuestra sorpresa, el método createDirectories() no contabilizó la mayor parte del tiempo de ejecución! ¡Nuestra prueba de referencia casera tardó aproximadamente la misma cantidad de tiempo en ejecutarse!

Además, si observamos el marco de encima, vemos que esto se debe principalmente a el método removeIf() , que contabiliza casi todo el tiempo de su llamador, update() .

Esto claramente necesita ser investigado.

Optimiza la prueba de referencia

Parece que el código responsable de eliminar eventos de la cola está realizando trabajo extra.

Dado que estamos utilizando una colección ordenada, y los eventos se agregan en orden cronológico, podemos estar seguros de que todos los elementos sujetos a eliminación siempre están al frente de la cola. Si reemplazamos removeIf() con un bucle que se rompe una vez que empieza a iterar sobre eventos que no va a remover, podríamos mejorar el rendimiento potencialmente:

// events.removeIf(aTime -> aTime < nanos - interval);
while (events.peekFirst() < nanos - interval) {
    events.removeFirst();
}

Cambiemos el código, volvamos a perfilar nuestra aplicación y miremos el resultado:

El sobrecosto de la lógica de la prueba de referencia es ahora mínimo, como debería ser, y el marco createDirectories() ahora ocupa aproximadamente el 95% de todo el tiempo de ejecución.

La mejora también es visible en la salida de la consola:

Average count: 14788 op
Spent time: 639 ms

Perfilado nativo

Habiendo resuelto el problema en la prueba de referencia, podríamos detenernos aquí y felicitarnos. Pero, ¿qué pasa con nuestro método createDirectories() ? ¿Es demasiado lento?

Parece que hay poco espacio para la optimización aquí, ya que este es un método de la biblioteca, y no tenemos control sobre su implementación. Aun así, el perfilador puede darnos una pista.

Al expandir los marcos de la biblioteca plegada, podemos inspeccionar lo que está sucediendo en su interior.

Esta parte del gráfico de llama muestra que el principal contribuyente al tiempo de ejecución de createDirectories() es sun.nio.fs.UnixNativeDispatcher.mkdir0 . Una gran parte de este marco no tiene nada encima de él. A esto se le conoce como self-time del método e indica que no hay código Java más allá de ese punto. Podría haber código nativo, eso sí.

Como estamos intentando crear un directorio, lo cual requiere llamar a la API del sistema operativo, podríamos esperar que el self-time de mkdir esté dominado por llamadas nativas. UnixNativeDispatcher en el nombre de la clase parece confirmar eso.

Habilitamos el perfilado nativo (Settings | Build, Execution, Deployment | Java Profiler | Collect native calls):

Reejecutar la aplicación con el perfilado nativo activado nos muestra la imagen completa:

Ahí está el problema. La documentación para el método createDirectories() dice:

La descripción es válida desde la perspectiva de Java, ya que no genera ninguna excepción de Java. Sin embargo, cuando se intenta crear un directorio que ya existe, se lanzan excepciones a nivel del sistema operativo. Esto conduce a un desperdicio significativo de recursos en nuestro escenario.

Intentemos evitar esto y envolvamos la llamada a createDirectories() en una comprobación Files.exists() :

Path p = Paths.get("./a/b");
if (!Files.exists(p)) {
    Files.createDirectories(p);
}

¡El programa se vuelve relámpago rápido!

Average count: 50000 op
Spent time: 87 ms

Ahora es unas 16 veces más rápido de lo que era originalmente. ¡Esta gestión de excepciones fue realmente costosa! Los resultados pueden variar según el hardware y el entorno, pero deberían ser impresionantes de todos modos.

Diferencia de instantáneas

Si estás utilizando IntelliJ Profiler, existe una herramienta útil que te permite comparar visualmente dos instantáneas. Para una explicación detallada y los pasos, te recomendaría referirte a la documentación. Aquí tienes un resumen breve de los resultados que muestra la diferencia:

Los marcos que faltan en la instantánea más nueva están resaltados en verde, mientras que los nuevos están coloreados de rojo. Si un marco tiene varios colores, esto significa que el marco está presente en ambas instantáneas, pero su tiempo de ejecución general ha cambiado.

Como se puede ver en la captura de pantalla anterior, la gran mayoría de las operaciones realizadas originalmente por nuestro programa eran innecesarias, y pudimos eliminarlas. CountEvents.update() está completamente en verde, lo que significa nuestro primer cambio dio lugar a una mejora en casi la totalidad del tiempo de ejecución del método. Agregar Files.exists() no fue una mejora del 100%, pero efectivamente eliminó createDirectories() de la instantánea, solo agregando 60 ms al tiempo de ejecución del programa.

Conclusión

En este escenario, usamos un perfil para detectar y solucionar un problema de rendimiento. También presenciamos cómo incluso una API bien conocida puede tener implicaciones que afectan seriamente los tiempos de ejecución de un programa Java. Esto nos muestra por qué el perfilado es una habilidad útil incluso si no estás optimizando para millones de transacciones por segundo.

En los próximos artículos consideraremos más casos de uso de perfilado y técnicas. ¡Mantente atento!

all posts ->

---

• Hecho por Igor Kulakov. ¡Diviértete!

• Suscribirse

• 
• 
• 
•