La piedra

Esta semana pasada he estado revisando el rendimiento de ciertos procesos intensivos en CPU que tenemos en Nextail. La funcionalidad de profiling de Java Flight Recorder y Java Mission Control se han convertido en mi martillo en estos casos.

Cada vez que lo uso caigo en el mismo error, así que he decidido escribir un post para ver si no tropiezo con la misma piedra la próxima vez.

Java Flight Recorder es una herramienta para hacer profiling: muestrea el estado de la JVM tomando, entre otros datos, capturas del stacktrace para saber por dónde pasa tu código. Si agregamos todos esos stacktraces estadísticamente tendremos por dónde pasa más nuestro código.

El código donde más tiempo esté nuestra aplicación en ejecución aparecerá más veces. Pero cuidado con esta afirmación, porque en el propio proceso de muestreo que hace la JVM y en la posterior agregación perdemos información de cuánto tiempo duró de verdad cada llamada a un método. Obtenemos información relativa, no absoluta.

Simplificando, si un método aparece 1000 veces no sabemos si se le llamó 100 veces y durante cada llamada se le tomaron 10 muestras, o si se le llamó 1000 veces y en cada llamada se le consiguió tomar sólo una muestra.

¿Sabemos de verdad cuánto tiempo dura la ejecución de cada método? ¡No! A menos que recurramos a otro tipo de técnicas de benchmarking que midan de verdad el tiempo de ejecución de cada método mediante algún tipo de instrumentación del código.

¿Por qué es importante? Porque no sabremos donde prestar atención:

  • al método que aparece 1000 veces
  • o al que llama a ese método que aparece tantas veces

Mejor con un ejemplo

Imaginad que tenéis una colección de objetos de negocio que tenéis que ordenar por algún criterio, y desgraciadamente no tuviéramos el método Collections.sort(). Tendríamos que implementar nosotros la ordenación.

Pasado el tiempo vemos que la aplicación tarda más de lo razonable. El negocio nos va bien, crecen los usuarios y el uso de la aplicación, pero cada vez es más lenta.

Decidimos realizar una sesión de profiling para ver dónde está perdiendo más tiempo la aplicación, y vemos algo como esto:

stack profile

¿Qué es lo primero que se nos viene a la cabeza? que el 90% del tiempo lo pasamos en el método Invoice.compare, por lo que está mal implementado o tiene alguna ineficiencia.

Nos volvemos locos cambiando código, haciendo benchmarking y viendo cómo podemos optimizar la comparación de enteros, sin conseguir mejorar el rendimiento.

¿Qué es lo que estará pasando realmente? ¿Dónde está el problema? ¡Lo más probable es que esté en el método sortInvoices! Aquel día que implementamos el método sort usamos la primera implementación que encontramos, y que además tenía un nombre gracioso: Cocktail_shaker_sort, pero no era precisamente el más rápido. Con 100 facturas iba bien, pero ahora tenemos millares!

¿Es lento el método Invoice.compare? ¡No! ¡Lo que pasa es que se le está llamando demasiadas veces!

La solución pasa por cambiar la implementación del método sort para evitar llamar tantas veces al método compare, no en cambiar la implementación del método compare.

Ahora, cambia el método sort por un proceso de negocio o algoritmo que implemente tu aplicación….. No siempre tu problema parece estar en el sitio más evidente, y hay que buscar la causa en otro lugar.

¿Y si lo extrapolamos a otro tipo de procesos? ¿Cuántos procesos/tareas de nuestro día a día creemos que son ineficientes y nos empeñamos en optimizarlos, pero resulta que lo que tenemos que cambiar está en otro sitio?