Más allá de cProfile: Elegir la herramienta adecuada para la optimización del rendimiento

Nota: Este artículo está basado en una charla que di en PyGotham 2019. Puedes ver el vídeo aquí.

Tu programa de Python es demasiado lento.Tal vez tu aplicación web no puede mantener el ritmo, o ciertas consultas están tomando mucho tiempo.Tal vez tienes un programa por lotes que tarda horas o incluso días en ejecutarse.

¿Cómo acelerar?

El proceso básico que probablemente siga es:

1. Elija la herramienta adecuada para medir la velocidad.
2. Use la herramienta para averiguar el cuello de botella.
3. Corregir el cuello de botella.

Este artículo se centrará en el primer paso: elegir la herramienta adecuada.Y en particular, cubrirá:

• cProfile: El perfilador determinista de la biblioteca estándar de Python.
• Pyinstrument: Un perfilador de muestreo.
• Eliot: Una biblioteca de registro.

No voy a entrar en una gran cantidad de detalles acerca de cómo utilizar estas herramientas, porque el objetivo es ayudarle a elegir la correcta. Pero voy a explicar lo que hacen estas herramientas, y cuándo y por qué usted elegiría uno sobre el otro.

cProfile: Un perfilador determinista

El perfilador cProfile está integrado en Python, así que probablemente haya oído hablar de él, y puede ser la herramienta que utilice por defecto.Funciona trazando cada llamada a una función en un programa.Por eso es un perfilador determinista: si lo ejecuta con las mismas entradas, dará la misma salida.

Por defecto cProfile mide la CPU del proceso-cuánta CPU ha utilizado su proceso hasta el momento.Siempre debes preguntar lo que tu perfilador está midiendo, porque diferentes medidas pueden detectar diferentes problemas.Medir la CPU significa que no puedes detectar la lentitud causada por otras causas, como la espera de una respuesta de una consulta a la base de datos.

Aunque cProfile está siempre disponible en tu instalación de Python, también tiene algunos problemas-y como verás, la mayoría de las veces no querrás usarlo.

Usando cProfile

Usar cProfile es bastante fácil.Si tienes un script que sueles ejecutar directamente así:

$ python benchmark.py7855 messages/sec

Entonces puedes simplemente poner el prefijo python -m cProfile para ejecutarlo bajo el perfilador:

También hay una API de perfilado de Python, así que puedes perfilar funciones concretas en un prompt del intérprete de Python o en un Jupyter notebook.

El formato de salida es una tabla, que no es ideal: cada fila es una llamada a una función que se ejecutó durante el período de tiempo perfilado, pero no se sabe cómo esa llamada a la función está relacionada con otras llamadas a la función.Así que si usted tiene una función que puede ser alcanzada desde múltiples rutas de código, puede ser difícil averiguar qué ruta de código fue responsable de llamar a la función lenta.

Lo que cProfile puede decirle

Si usted mira la tabla anterior, puede ver que:

• _output.py(__call__) fue llamado 50.000 veces. Es un número par porque se trata de un script de referencia que ejecuta el mismo código en un bucle 10.000 veces.Si no estaba llamando deliberadamente a una función muchas veces, esto puede ser útil para detectar un alto número de llamadas es útil para identificar los bucles internos ocupados.
• _output.py(send) utilizó 0,618 segundos de CPU (incluyendo el tiempo de CPU de las funciones que llamó), y 0,045 segundos de CPU (sin incluir las funciones que llamó).

Usando esta información puede detectar funciones lentas que puede optimizar -lentas en cuanto a la CPU, de todos modos.

Cómo funciona

cProfile mide cada una de las llamadas de función.En particular, cada llamada de función en la ejecución se envuelve así:

start = process_time()try: f()finally: elapsed = process_time() - start

El perfilador registra el tiempo de CPU al inicio y al final, y la diferencia se asigna a la cuenta de esa función.

Los problemas de cProfile

Aunque cProfile está siempre disponible en cualquier instalación de Python, también sufre algunos problemas importantes.

Problema nº 1: Elevada sobrecarga y resultados distorsionados

Como puedes imaginar, hacer un trabajo extra para cada llamada a una función tiene algunos costes:

$ python benchmark.py7855 messages/sec$ python -m cProfile benchmark.py5264 messages/sec... cProfile output ...

Nota la lentitud de la ejecución de cProfile.Y lo que es peor, la ralentización no es uniforme en todo el programa: como está ligado al número de llamadas a funciones, las partes de tu código con más llamadas a funciones se ralentizarán más.Así que esta sobrecarga puede distorsionar los resultados.

Problema #2: Demasiada información

Si recuerdas la salida de cProfile que vimos anteriormente, incluye una fila para cada función que fue llamada durante la ejecución del programa.La mayoría de esas llamadas de función son irrelevantes para nuestro problema de rendimiento: se ejecutan rápidamente, y sólo una o dos veces.

Así que cuando estás leyendo la salida de cProfile, estás lidiando con un montón de ruido extra que enmascara la señal.

Problema nº 3: Medición offline del rendimiento

Muy a menudo su programa sólo será lento cuando se ejecute en condiciones del mundo real, con entradas del mundo real.Quizás sólo determinadas consultas de los usuarios ralentizan su aplicación web, y usted no sabe qué consultas.Quizás su programa por lotes sólo es lento con datos reales.

Pero cProfile, como hemos visto, ralentiza bastante su programa, por lo que probablemente no querrá ejecutarlo en su entorno de producción.Así que mientras la lentitud sólo es reproducible en producción, cProfile sólo le ayuda en su entorno de desarrollo.

Problema nº 4: El rendimiento se mide sólo para las funciones

cProfile puede decirle «slowfunc() es lento», donde promedia todas las entradas de esa función.Y eso está bien si la función es siempre lenta.

Pero a veces tienes algún código algorítmico que sólo es lento para entradas específicas.Es muy posible que:

• slowfunc(100) sea rápido.
• slowfunc(0) sea lento.

cProfile no podrá decirle qué entradas causaron la lentitud, lo que puede hacer más difícil diagnosticar el problema.

cProfile: Generalmente insuficiente

Como resultado de estos problemas, cProfile no debería ser su herramienta de rendimiento de elección.En su lugar, a continuación vamos a hablar de dos alternativas:

• Pyinstrument resuelve los problemas #1 y #2.
• Eliot resuelve los problemas #3 y #4.

Pyinstrument: un perfilador de muestreo

Pyinstrument resuelve dos de los problemas que cubrimos anteriormente:

• Tiene menor sobrecarga que cProfile, y no distorsiona los resultados.
• Filtra las llamadas a funciones irrelevantes, por lo que hay menos ruido.

Pyinstrument mide el tiempo de reloj de pared transcurrido, no el tiempo de la CPU, por lo que puede detectar la lentitud causada por las solicitudes de red, las escrituras en disco, la contención de bloqueos, etc.

Cómo se usa

El uso de Pyinstrument es similar al de cProfile; sólo tiene que añadir un prefijo a su script:

$ python benchmark.py7561 messages/sec$ python -m pyinstrument benchmark.py6760 messages/sec... pyinstrument output ...

Nota que tiene algo de sobrecarga, pero no tanto como cProfile-y la sobrecarga es uniforme.

Pyinstrument también tiene una API de Python, por lo que se puede utilizar para perfilar piezas particulares de código en un intérprete interactivo de Python o un cuaderno Jupyter.

La salida

La salida de Pyinstrument es un árbol de llamadas, midiendo el tiempo del reloj de pared:

A diferencia de la fila por función de cProfile, Pyinstrument le da un árbol de llamadas a la función, para que pueda ver el contexto de la lentitud.Una función podría aparecer varias veces si la lentitud es causada por múltiples rutas de código.

Como resultado, la salida de Pyinstrument es mucho más fácil de interpretar, y le da una mejor comprensión de la estructura de rendimiento de su programa que la salida por defecto de cProfile.

Cómo funciona (edición gato)

Imagine que tiene un gato.Desea saber cómo ese gato pasa su tiempo.

Podrías espiar cada uno de sus momentos, pero eso sería mucho trabajo.Así que en su lugar decides tomar muestras: cada 5 minutos metes la cabeza en la habitación donde está el gato, y anotas lo que está haciendo.

Por ejemplo:

• 12:00: Durmiendo 💤
• 12:05: Durmiendo 💤
• 12:10: Comiendo 🍲
• 12:15: Usando la caja de arena 💩
• 12:20: Durmiendo 💤
• 12:25: Durmiendo 💤
• 12:30: Durmiendo 💤

Unos días después puedes resumir tus observaciones:

• 80%: Durmiendo 💤
• 10%: Comiendo 🍲
• 9%: Usar la caja de arena 💩
• 1%: Mirar con anhelo a través de la ventana a los pájaros 🐦

Entonces, ¿hasta qué punto es preciso este resumen? En la medida en que tu objetivo es medir dónde pasó el gato la mayor parte de su tiempo, probablemente sea preciso.Y cuanto más frecuentes sean las observaciones (==muestras) y más observaciones hagas, más preciso será el resumen.

Si su gato pasa la mayor parte de su tiempo durmiendo, esperaría que la mayoría de las observaciones muestreadas mostraran que está durmiendo.Y sí, se perderá algunas actividades rápidas y raras-pero para los propósitos de «en qué pasó el gato la mayor parte de su tiempo» esas actividades rápidas y raras son irrelevantes.

Cómo funciona (edición de software)

Al igual que nuestro gato, Pyinstrument muestrea el comportamiento de un programa Python a intervalos: cada 1ms comprueba qué función se está ejecutando en ese momento.Eso significa:

• Si una función es acumulativamente lenta, aparecerá a menudo.
• Si una función es acumulativamente rápida, por lo general no la veremos en absoluto.

Eso significa que nuestro resumen de rendimiento tiene menos ruido: las funciones que apenas se utilizan serán omitidas en su mayoría.Pero en general el resumen es bastante preciso en términos de cómo el programa pasó su tiempo, siempre y cuando tomemos suficientes muestras.

Eliot: Una biblioteca de registro

La última herramienta que cubriremos en detalle es Eliot, una biblioteca de registro que escribí.Resuelve los otros dos problemas que vimos con cProfile:

• El registro puede utilizarse en producción.
• El registro puede registrar los argumentos de las funciones.

Como verás, Eliot proporciona algunas capacidades únicas que lo hacen mejor para registrar el rendimiento que las bibliotecas de registro normales.Dicho esto, con un poco de trabajo extra puedes obtener los mismos beneficios de otras bibliotecas de registro también.

Añadir registro al código existente

Considere el siguiente esquema de un programa:

Podemos tomar este código y añadirle algo de registro:

Específicamente, hacemos dos cosas:

1. Indicar a Eliot dónde debe salir los mensajes de registro (en este caso, un fichero llamado «out.log»).
2. Decoramos las funciones con un decorador @log_call.Esto registrará el hecho de que la función fue llamada, sus argumentos, y el valor de retorno (o la excepción lanzada).

Eliot tiene otras APIs más finas, pero @log_call es suficiente para demostrar los beneficios del registro.

Salida de eliot

Una vez que ejecutamos el programa, podemos mirar los registros usando una herramienta llamada eliot-tree:

Nota que, un poco como Pyinstrument, estamos mirando un árbol de acciones.He simplificado un poco la salida-originalmente para que pudiera caber en una diapositiva que utilicé en la versión de la charla de este artículo-pero incluso en un artículo en prosa nos permite centrarnos en el aspecto del rendimiento.

En Eliot, cada acción tiene un inicio y un final, y puede iniciar otras acciones-de ahí el árbol resultante.Dado que sabemos cuándo empieza y termina cada acción registrada, también sabemos cuánto tiempo ha tardado.

En este caso, cada acción se asigna uno a uno con una llamada a una función.Y hay algunas diferencias con respecto a la salida de Pyinstrument:

1. En lugar de combinar múltiples llamadas a funciones, se ve cada llamada individual por separado.
2. Puedes ver los argumentos y el resultado de retorno de cada llamada.
3. Puedes ver el tiempo de reloj de pared transcurrido de cada acción.

Por ejemplo, puedes ver que multiplysum() tardó 10 segundos, pero la gran mayoría del tiempo se gastó en multiply(), con las entradas de 3 y 4.Así que inmediatamente sabes que para la optimización del rendimiento quieres centrarte en multiply(), y tienes algunas entradas iniciales (3 y 4) con las que jugar.

Las limitaciones del registro

El registro no es suficiente por sí mismo como fuente de información sobre el rendimiento.

En primer lugar, sólo obtienes información del código donde has añadido explícitamente llamadas de registro.Un perfilador puede ejecutarse en cualquier pieza arbitraria de código sin preparación previa, pero con el registro tienes que hacer algo de trabajo por adelantado.

Si no agregaste código de registro, no obtendrás ninguna información.Eliot hace esto un poco mejor, ya que la estructura de árbol de acciones te da una idea de dónde se gastó el tiempo, pero todavía no es suficiente si el registro es demasiado escaso.

Segundo, no puedes añadir logging en todas partes porque eso ralentizará tu programa.El logging no es barato-es una sobrecarga mayor que la de cProfile.Así que tienes que añadirlo con criterio, en puntos clave donde se maximice la información que da sin afectar al rendimiento.

Elegir las herramientas adecuadas

¿Cuándo debe utilizar cada herramienta?

Añadir siempre el registro

Cualquier programa que no sea trivial probablemente necesite algún registro, aunque sólo sea para detectar fallos y errores.Y si ya está añadiendo el registro, puede tomarse la molestia de registrar la información que necesita para hacer la depuración del rendimiento también.

Eliot lo hace más fácil, ya que el registro de las acciones inherentemente le da el tiempo transcurrido, pero usted puede con un poco de trabajo extra hacer esto con cualquier biblioteca de registro.

El registro puede ayudarle a detectar el lugar específico donde su programa es lento, y por lo menos algunas entradas que causan lentitud, pero a menudo es insuficiente.Así que el siguiente paso es utilizar un perfilador, y en particular un perfilador de muestreo como Pyinstrument:

• Tiene poca sobrecarga, y lo más importante es que no distorsiona los resultados.
• Mide el tiempo del reloj de pared, por lo que no asume que la CPU es el cuello de botella.
• Sólo muestra las funciones más lentas, omitiendo las funciones rápidas irrelevantes.

Use cProfile si necesita una métrica de coste personalizada

Si alguna vez necesita escribir un perfil personalizado, cProfile le permite introducir diferentes funciones de coste, convirtiéndolo en una herramienta fácil para medir métricas más inusuales.

Puede medir:

• No-CPU, todo el tiempo de espera de los eventos que no son de la CPU.
• El número de cambios de contexto voluntarios, es decir, el número de llamadas al sistema que tardan mucho tiempo.
• Las asignaciones de memoria.
• Más ampliamente, cualquier contador que suba.

TL;DR

Como un buen punto de partida en las herramientas de optimización del rendimiento, le sugiero que:

1. Loguee las entradas y salidas clave, y el tiempo transcurrido de las acciones clave, utilizando Eliot o alguna otra biblioteca de registro.
2. Utilizar Pyinstrument-u otro perfilador de muestreo-como su perfilador por defecto.
3. Utilizar cProfile cuando si necesita un perfilador personalizado.