Profiler Python en utilisant cProfile : un cas concret

Écrire des programmes est amusant, mais les rendre rapides peut être une douleur. Les programmes Python ne font pas exception à cette règle, mais la chaîne d’outils de profilage de base n’est en fait pas si compliquée à utiliser. Ici, je voudrais vous montrer comment vous pouvez rapidement profiler et analyser votre code Python pour trouver quelle partie du code vous devriez optimiser.

Profiler un programme Python, c’est faire une analyse dynamique qui mesure le temps d’exécution du programme et tout ce qui le compose. Cela signifie mesurer le temps passé dans chacune de ses fonctions. Cela vous donnera des données sur l’endroit où votre programme passe du temps, et sur la zone qui pourrait mériter d’être optimisée.

C’est un exercice très intéressant. Beaucoup de gens se concentrent sur les optimisations locales, comme déterminer par exemple laquelle des fonctions Python range ou xrange va être plus rapide. Il s’avère que savoir laquelle est plus rapide peut ne jamais être un problème dans votre programme, et que le temps gagné par l’une des fonctions ci-dessus pourrait ne pas valoir le temps que vous passez à faire des recherches à ce sujet, ou à en discuter avec votre collègue.

Tenter d’optimiser aveuglément un programme sans mesurer où il passe réellement son temps est un exercice inutile. Suivre ses tripes seules n’est pas toujours suffisant.

Il existe de nombreux types de profilage, comme il existe de nombreuses choses que vous pouvez mesurer. Dans cet exercice, nous allons nous concentrer sur le profilage de l’utilisation du CPU, c’est-à-dire le temps passé par chaque fonction à exécuter des instructions. Évidemment, nous pourrions faire beaucoup plus de types de profilage et d’optimisations, comme le profilage de la mémoire qui mesurerait la mémoire utilisée par chaque morceau de code – quelque chose dont je parle dans The Hacker’s Guide to Python.

cProfile

Depuis Python 2.5, Python fournit un module C appelé cProfile qui a un overhead raisonnable et offre un ensemble de fonctionnalités assez bon. L’utilisation de base se résume à :

Bien que vous puissiez également exécuter un script avec lui, ce qui s’avère être pratique :

Cela imprime toutes les fonctions appelées, avec le temps passé dans chacune et le nombre de fois qu’elles ont été appelées.

Visualisation avancée avec KCacheGrind

Bien qu’étant utile, le format de sortie est très basique et ne rend pas facile la saisie des connaissances pour les programmes complets. Pour une visualisation plus avancée, je m’appuie sur KCacheGrind. Si vous avez fait de la programmation et du profilage en C ces dernières années, vous l’avez peut-être utilisé car il est principalement conçu comme front-end pour les call-graphes générés par Valgrind.

Pour l’utiliser, vous devez générer un fichier de résultat cProfile, puis le convertir au format KCacheGrind. Pour cela, j’utilise pyprof2calltree.

$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprof

Et la fenêtre KCacheGrind apparaît comme par magie !

Cas concret : Optimisation de Carbonara

J’étais curieux des performances de Carbonara, la petite bibliothèque de séries temporelles que j’ai écrite pour Gnocchi. J’ai décidé de faire un profilage de base pour voir s’il y avait une optimisation évidente à faire.

Pour profiler un programme, il faut l’exécuter. Mais exécuter le programme entier en mode profilage peut générer beaucoup de données dont vous ne vous souciez pas, et ajoute du bruit à ce que vous essayez de comprendre. Comme Gnocchi a des milliers de tests unitaires et quelques-uns pour Carbonara lui-même, j’ai décidé de profiler le code utilisé par ces tests unitaires, car c’est un bon reflet des fonctionnalités de base de la bibliothèque.

Notez que c’est une bonne stratégie pour un profilage de premier passage curieux et naïf.
Il n’y a aucun moyen de s’assurer que les points chauds que vous verrez dans les tests unitaires sont les points chauds réels que vous rencontrerez en production. Par conséquent, un profilage dans des conditions et avec un scénario qui imite ce qui est vu en production est souvent une nécessité si vous devez pousser plus loin l’optimisation de votre programme et si vous voulez obtenir un gain perceptible et valable.

J’ai activé cProfile en utilisant la méthode décrite ci-dessus, en créant un objet cProfile.Profile autour de mes tests (j’ai en fait commencé à implémenter cela dans testtools). J’ai ensuite lancé KCacheGrind comme décrit ci-dessus. En utilisant KCacheGrind, j’ai généré les chiffres suivants.

Le test que j’ai profilé ici s’appelle test_fetch et est assez facile à comprendre : il met des données dans un objet timeserie, puis récupère le résultat agrégé. La liste ci-dessus montre que 88 % des ticks sont passés dans set_values (44 ticks sur 50). Cette fonction est utilisée pour insérer des valeurs dans la timeserie, pas pour récupérer les valeurs. Cela signifie qu’elle est vraiment lente pour insérer des données, et plutôt rapide pour les récupérer réellement.

La lecture du reste de la liste indique que plusieurs fonctions se partagent le reste des ticks, update, _first_block_timestamp, _truncate, _resample, etc. Certaines des fonctions de la liste ne font pas partie de Carbonara, il est donc inutile de chercher à les optimiser. La seule chose qui peut être optimisée est, parfois, le nombre de fois qu’elles sont appelées.

Le graphe des appels me donne un peu plus d’indications sur ce qui se passe ici. En utilisant mes connaissances sur le fonctionnement de Carbonara, je ne pense pas que toute la pile à gauche pour _first_block_timestamp ait beaucoup de sens. Cette fonction est censée trouver le premier horodatage pour un agrégat, par exemple, avec un horodatage de 13:34:45 et une période de 5 minutes, la fonction devrait retourner 13:30:00. La façon dont cela fonctionne actuellement est d’appeler la fonction resample de Pandas sur une timeserie avec un seul élément, mais cela semble être très lent. En effet, actuellement cette fonction représente 25 % du temps passé par set_values (11 ticks sur 44).

Heureusement, j’ai récemment ajouté une petite fonction appelée _round_timestamp qui fait exactement ce dont _first_block_timestamp a besoin que sans appeler aucune fonction Pandas, donc pas de resample. J’ai donc fini par réécrire cette fonction de cette façon:

Et puis j’ai relancé exactement le même test pour comparer la sortie de cProfile.

La liste des fonctions semble assez différente cette fois. Le nombre de temps passé utilisé par set_values a chuté de 88 % à 71 %.

La pile d’appel de set_values le montre assez bien : on ne voit même pas la fonction _first_block_timestamp car elle est tellement rapide qu’elle a totalement disparu de l’affichage. Elle est maintenant considérée comme insignifiante par le profiler.

Donc nous venons d’accélérer tout le processus d’insertion des valeurs dans Carbonara d’un joli 25 % en quelques minutes. Pas si mal pour une première passe naïve, non ?

Si vous voulez en savoir plus, j’ai écrit un chapitre entier sur l’optimisation du code dans Scaling Python. Jetez-y un coup d’œil !