Empezando con el Continuous Profiler
La generación de perfiles puede hacer que tus servicios sean más rápidos, baratos y fiables. Sin embargo, si es la primera vez que utilizas un generador de perfiles, puede resultarte confuso.
En esta guía, te explicamos en qué consiste la generación de perfiles, te ofrecemos el ejemplo de un servicio con un problema de rendimiento, y utilizamos el Continuous Profiler de Datadog para entender y solucionar el problema.
Los generadores de perfiles recopilan datos sobre el programa mientras este se ejecuta para reflejar la cantidad de “trabajo” que realiza cada función. Por ejemplo, si la monitorización de la infraestructura demuestra que los servidores de tu aplicación están usando el 80 % de su CPU, es posible que no sepas a qué se debe. Por este motivo, la generación de perfiles ofrece un desglose del trabajo. Por ejemplo:
| Función | Uso de la CPU |
|---|
doSomeWork | 48 % |
renderGraph | 19 % |
| Otro | 13 % |
Esta información es importante cuando se trabaja para solucionar problemas de rendimiento, dado que hay muchos programas que pasan demasiado tiempo en unos pocos lugares, lo que no siempre es evidente. Averiguar qué partes de un programa deben optimizarse constituye una gran pérdida de tiempo para los ingenieros, que a cambio obtienen resultados poco satisfactorios. Si utilizas un generador de perfiles, puedes identificar exactamente qué partes del código hay que optimizar.
Si has usado una herramienta de APM, es posible que la generación de perfiles te parezca un rastreador “más detallado” que ofrece una imagen pormenorizada del código sin necesidad de recurrir a la instrumentación.
El Continuous Profiler de Datadog puede rastrear varios tipos de “trabajo”, como el uso de la CPU, la cantidad y los tipos de objetos que se asignan en la memoria, el tiempo de espera para adquirir bloqueos, la cantidad de E/S de la red o archivo, y más. Los tipos de perfiles disponibles dependen del lenguaje cuyo perfil se esté generando.
Configuración
Requisitos previos
Antes de empezar, asegúrate de que cumples los siguientes requisitos previos:
- docker-compose
- Una cuenta de Datadog y una clave de API. Si necesitas una cuenta de Datadog, regístrate para disfrutar de una prueba gratuita.
Instalación
El repositorio dd-continuous-profiler-example ofrece un ejemplo de servicio con un problema de rendimiento para experimentar. Se incluye una API para realizar búsquedas en una “base de datos” de 5000 películas.
Instala y ejecuta el servicio del ejemplo:
clonar git https://github.com/DataDog/dd-continuous-profiler-example.git
cd dd-continuous-profiler-example
echo "DD_API_KEY=YOUR_API_KEY" > docker.env
docker-compose up -d
Validación
Una vez que se hayan creado los contenedores y estén en ejecución, podrás explorar el contenedor “toolbox”:
docker exec -it dd-continuous-profiler-example-toolbox-1 bash
Usa la API con:
curl -s http://movies-api-java:8080/movies?q=wars | jq
También existe una versión Python del servicio del ejemplo denominada movies-api-py. Si optas por utilizarla, ajusta los comandos del tutorial como corresponda.
Generar datos
Usa la herramienta ApacheBench, ab, para generar tráfico. Ejecútala con 10 clientes HTTP simultáneos y envía las solicitudes cada 20 segundos. En el contenedor “toolbox”, ejecuta:
ab -c 10 -t 20 http://movies-api-java:8080/movies?q=the
Resultado del ejemplo:
...
Latencias declaradas por ab:
Porcentaje de solicitudes atendidas en un tiempo determinado (ms)
50 % 464
66 % 503
75 % 533
80 % 553
90 % 614
95 % 683
98 % 767
99 % 795
100 % 867 (solicitud más larga)
Investigar
Lee el perfil
Utiliza la Búsqueda de perfiles para encontrar el perfil que estuvo activo durante el intervalo de tiempo en el que generaste el tráfico. Es posible que tarde alrededor de un minuto en cargarse. El perfil que tiene el test de carga presenta un uso superior de la CPU:
Cuando lo abras, la visualización del perfil será parecida a esta:
Esto es un gráfico de llamas. Lo más importante de todo lo que muestra es la cantidad de CPU que usa cada método (dado que estamos ante un perfil de CPU) y cómo se invocaron estos métodos. Por ejemplo, en la segunda fila empezando por arriba, verás que Thread.run() invocó a QueuedThreadPool$2.run() (entre otras cosas), que a su vez invocó a QueuedThreadPool.runjob(Runnable), que invocó a ReservedTheadExecutor$ReservedThread.run(), y así sucesivamente.
Al ampliar una zona de la parte inferior del gráfico de llamas, aparece un cuadro de información que indica que la CPU dedicó aproximadamente 309 ms (el 0,90 %) de su tiempo a la función parse():
String.length() se encuentra justo debajo de la función parse(), lo que significa que la invoca parse(). Pasa el cursor por encima de String.length() para ver que la CPU le dedicó alrededor de 112 ms de su tiempo:
Eso quiere decir que se le dedicaron 197 milisegundos directamente a parse(): 309 ms - 112 ms. La representación visual es la parte del cuadro parse() que no tiene nada debajo.
Cabe destacar que el gráfico de llamas no representa la progresión del tiempo. Si nos fijamos en esta parte del perfil, Gson$1.write() no se ejecutó antes que TypeAdapters$16.write(), pero puede ser que tampoco lo haya hecho después.
Es probable que se hayan ejecutado de forma simultánea o que el programa haya invocado varias veces uno, luego el otro, y así sucesivamente. El gráfico de llamas fusiona todas las veces que un programa ejecutó la misma serie de funciones para que puedas ver en un pestañeo qué partes del código usaron más CPU, sin un montón de campos diminutos que se muestran cada vez que se invoca una función.
Aleja la imagen y fíjate en que alrededor del 87 % del uso de la CPU se produjo en el método replyJSON(). Más abajo, la gráfica muestra replyJSON(), y los métodos que invoca se terminan bifurcando en cuadro rutas de código principales (“stack traces”) que ejecutan funciones relacionadas con el orden y el parseo de fechas:
Además, puedes observar que una parte del perfil de la CPU se representa de este modo:
Tipos de perfiles
La CPU dedicó casi un 6 % del tiempo a la recopilación de elementos no usados, lo que indica que podría estar produciendo una gran cantidad de basura. Por tanto, conviene revisar el tipo de perfil correspondiente a la Memoria asignada:
En un perfil de tipo “Memoria asignada”, el tamaño de los cuadros indica la cantidad de memoria asignada por cada función, así como el stack de llamada que provocó que la función efectuase dicha asignación. Como puedes observar a continuación, en este perfil de un minuto, el método replyJSON() y otros métodos invocados asignaron 17,47 GiB, la mayoría relacionados con el mismo código de parseo de fechas que hemos visto en el perfil de la CPU de arriba:
Solución
Corrige el código
Revisa el código y fíjate en lo que ocurre. En el gráfico de llamas de la CPU, verás que las rutas de código costosas pasan por una función lambda en la línea 66 que, a su vez, invoca a LocalDate.parse():
Esto se corresponde con esta parte del código en dd-continuous-profiler-example, donde se invoca a LocalDate.parse():
estático privado de java<Movie> sortByDescReleaseDate[Película<Movie> de flujo (stream)] {
devolver movies.sorted(Comparator.comparing((Película m) -> {
// Problema: Parseo de una fecha y hora para cada elemento que se clasificará.
// Solución de ejemplo:
// Ya que la fecha está en formato ISO (aaaa-mm-dd), ese se ordena bien con la clasificación de cadenas normal.
// `return m.releaseDate`
intentar {
devolver LocalDate.parse(m.releaseDate);
} capturar (Excepción e) {
devolver LocalDate.MIN;
}
}).inverso());
}
Esta es la lógica de ordenación que se aplica en la API, en la que los resultados se reflejan en orden descendente según la fecha de lanzamiento. Para ello, la API usa la fecha de lanzamiento en formato LocalDate a modo de clave de ordenación. Para ahorrar tiempo, podrías almacenar el parámetro LocalDate en caché para que solo se parsee la fecha de lanzamiento de cada película en vez de todas las solicitudes. No obstante, existe una solución mejor: parsear las fechas con el formato de la ISO 8601 (aaaa-mm-dd) para que se puedan ordenar como segmentos y no como parseos.
Reemplaza las secciones try y catch por return m.releaseDate; de esta forma:
estático privado de java<Movie> sortByDescReleaseDate[Película<Movie> de Flujo (stream)] {
devolver movies.sorted(Comparator.comparing((Película m) -> {
devolver m.releaseDate;
}).reversed());
}
Después, vuelve a crear y reinicia el servicio:
docker-compose crear movies-api-java
docker-compose up -d
Repite el test
Para comprobar la exactitud de los resultados, vuelve a generar tráfico:
docker exec -it dd-continuous-profiler-example-toolbox-1 bash
ab -c 10 -t 20 http://movies-api-java:8080/movies?q=the
Resultado del ejemplo:
Latencias declaradas por ab:
Porcentaje de solicitudes atendidas en un margen de tiempo determinado (ms)
50 % 82
66 % 103
75 % 115
80 % 124
90 % 145
95 % 171
98 % 202
99 % 218
100 % 315 (solicitud más larga)
p99 pasó de 795 ms a 218 ms y, por lo general, esta velocidad es entre cuatro y seis veces más rápida que antes.
Localiza el perfil que contiene el nuevo test de carga y fíjate en el perfil de la CPU. Las partes replyJSON del gráfico de llamas presentan un porcentaje de uso de la CPU mucho más pequeño que el test de carga anterior:
Haz una limpieza
Cuando termines de explorar, ejecuta el siguiente comando para hacer una limpieza:
Recomendaciones
Ahorrar dinero
Esta mejora del uso de la CPU puede traducirse en un ahorro de dinero. Si hubiera sido un servicio real, esta pequeña mejora podría haberte permitido reducir a la mitad el número de servidores, lo que supondría un ahorro de miles de dólares al año. No está nada mal para algo que llevó 10 minutos de trabajo.
Mejora tu servicio
Esta guía solo ha tratado la generación de perfiles de forma superficial, pero debería servirte para empezar. Habilita el generador de perfiles para tus servicios.
Leer más
Más enlaces, artículos y documentación útiles:
