Escribir programas es divertido, pero hacerlos rápidos puede ser un dolor. Los programas de Python no son una excepción, pero la cadena de herramientas de perfilado básico no es en realidad tan complicada de usar. Aquí, me gustaría mostrarte cómo puedes perfilar y analizar rápidamente tu código Python para encontrar qué parte del código deberías optimizar.
Perfilar un programa Python es hacer un análisis dinámico que mide el tiempo de ejecución del programa y todo lo que lo compone. Es decir, medir el tiempo empleado en cada una de sus funciones. Esto te dará datos sobre dónde gasta el tiempo tu programa, y qué área podría valer la pena optimizar.
Es un ejercicio muy interesante. Mucha gente se centra en las optimizaciones locales, como determinar, por ejemplo, cuál de las funciones de Python range o xrange va a ser más rápida. Resulta que saber cuál es más rápida puede no ser nunca un problema en tu programa, y que el tiempo ganado por una de las funciones anteriores puede no valer el tiempo que dedicas a investigar eso, o a discutirlo con tu colega.
Tratar de optimizar a ciegas un programa sin medir en qué está gastando realmente su tiempo es un ejercicio inútil. Seguir sólo las tripas no siempre es suficiente.
Hay muchos tipos de perfiles, como hay muchas cosas que se pueden medir. En este ejercicio, nos centraremos en el perfilado de la utilización de la CPU, es decir, el tiempo que pasa cada función ejecutando instrucciones. Obviamente, podríamos hacer muchos más tipos de perfilado y optimizaciones, como el perfilado de memoria que mediría la memoria utilizada por cada trozo de código – algo de lo que hablo en The Hacker’s Guide to Python.
cProfile
Desde Python 2.5, Python proporciona un módulo de C llamado cProfile que tiene una sobrecarga razonable y ofrece un conjunto de características bastante bueno. El uso básico se reduce a:
Aunque también se puede ejecutar un script con él, que resulta muy práctico:
Este imprime todas las funciones llamadas, con el tiempo empleado en cada una y el número de veces que han sido llamadas.
Visualización avanzada con KCacheGrind
Aunque es útil, el formato de salida es muy básico y no facilita la obtención de conocimientos para programas completos. Para una visualización más avanzada, aprovecho KCacheGrind. Si has hecho algo de programación y perfilado en C estos últimos años, es posible que lo hayas utilizado, ya que está diseñado principalmente como front-end para los call-graphs generados por Valgrind.
Para utilizarlo, necesitas generar un archivo de resultados cProfile, y luego convertirlo al formato KCacheGrind. Para ello, utilizo pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprof¡Y la ventana de KCacheGrind aparece mágicamente!
Caso concreto: Optimización de Carbonara
Tenía curiosidad por las prestaciones de Carbonara, la pequeña librería de series temporales que escribí para Gnocchi. Decidí hacer un perfilado básico para ver si había alguna optimización obvia que hacer.
Para perfilar un programa, hay que ejecutarlo. Pero ejecutar todo el programa en modo de perfilado puede generar un montón de datos que no te interesan, y añade ruido a lo que estás tratando de entender. Dado que Gnocchi tiene miles de pruebas unitarias y unas cuantas para Carbonara en sí, decidí perfilar el código utilizado por estas pruebas unitarias, ya que es un buen reflejo de las características básicas de la biblioteca.
Nota que esta es una buena estrategia para un perfilado curioso e ingenuo de primera pasada.
No hay manera de que puedas asegurarte de que los hotspots que verás en las pruebas unitarias son los hotspots reales que encontrarás en producción. Por lo tanto, un perfil en condiciones y con un escenario que imita lo que se ve en la producción es a menudo una necesidad si usted necesita para empujar su optimización del programa más allá y quiere lograr la ganancia perceptible y valiosa.
Activé cProfile utilizando el método descrito anteriormente, la creación de un objeto cProfile.Profile alrededor de mis pruebas (en realidad empecé a implementar que en testtools). A continuación, ejecuto KCacheGrind como se ha descrito anteriormente. Usando KCacheGrind, generé las siguientes cifras.
La prueba que perfilé aquí se llama test_fetch y es bastante fácil de entender: pone los datos en un objeto timeserie, y luego obtiene el resultado agregado. La lista anterior muestra que el 88 % de los ticks se gastan en set_values (44 ticks sobre 50). Esta función se utiliza para insertar valores en la timeserie, no para obtener los valores. Eso significa que es muy lento para insertar datos, y bastante rápido para recuperarlos.
La lectura del resto de la lista indica que varias funciones comparten el resto de los ticks, update, _first_block_timestamp, _truncate, _resample, etc. Algunas de las funciones de la lista no forman parte de Carbonara, por lo que no tiene sentido buscar su optimización. Lo único que se puede optimizar es, a veces, el número de veces que se llaman.
El gráfico de llamadas me da un poco más de luz sobre lo que está pasando aquí. Usando mis conocimientos sobre cómo funciona Carbonara, no creo que toda la pila de la izquierda para _first_block_timestamp tenga mucho sentido. Se supone que esta función debe encontrar la primera marca de tiempo para un agregado, por ejemplo, con una marca de tiempo de 13:34:45 y un periodo de 5 minutos, la función debería devolver 13:30:00. La forma en que funciona actualmente es llamando a la función resample de Pandas en un timeserie con un solo elemento, pero eso parece ser muy lento. De hecho, actualmente esta función representa el 25 % del tiempo empleado por set_values (11 ticks en 44).
Afortunadamente, hace poco añadí una pequeña función llamada _round_timestamp que hace exactamente lo que _first_block_timestamp necesita que sin llamar a ninguna función de Pandas, por lo que no hay resample. Así que terminé reescribiendo esa función de esta manera:
Y luego volví a ejecutar exactamente la misma prueba para comparar la salida de cProfile.
La lista de la función parece bastante diferente esta vez. El número de tiempo utilizado por set_values ha bajado del 88 % al 71 %.
La pila de llamadas para set_values lo muestra bastante bien: ni siquiera podemos ver la función _first_block_timestamp ya que es tan rápida que ha desaparecido totalmente de la pantalla. Ahora se considera insignificante por el perfilador.
Así que acabamos de acelerar todo el proceso de inserción de valores en Carbonara en un bonito 25 % en pocos minutos. No está tan mal para una primera pasada ingenua, ¿verdad?
Si quieres saber más, escribí un capítulo entero sobre la optimización de código en Scaling Python. Échale un vistazo!