Au-delà de cProfile : Choisir le bon outil pour l’optimisation des performances

Note : Cet article est basé sur une conférence que j’ai donnée à PyGotham 2019. Vous pouvez regarder la vidéo ici.

Votre programme Python est trop lent.Peut-être que votre application web n’arrive pas à suivre, ou que certaines requêtes prennent beaucoup de temps.Peut-être que vous avez un programme batch qui prend des heures ou même des jours à s’exécuter.

Comment accélérer ?

Le processus de base que vous êtes susceptible de suivre est :

1. Choisir le bon outil pour mesurer la vitesse.
2. Utiliser l’outil pour déterminer le goulot d’étranglement.
3. Fixer le goulot d’étranglement.

Cet article se concentrera sur la première étape : choisir le bon outil.Et en particulier, il couvrira :

• cProfile : Le profileur déterministe de la bibliothèque standard de Python.
• Pyinstrument : Un profileur d’échantillonnage.
• Eliot : Une bibliothèque de journalisation.

Je ne vais pas entrer dans une quantité énorme de détails sur la façon d’utiliser ces outils, car le but est de vous aider à choisir le bon. Mais je vais expliquer ce que font ces outils, et quand et pourquoi vous choisiriez l’un plutôt que l’autre.

cProfile : Un profiler déterministe

Le profiler cProfile est intégré à Python, donc vous en avez probablement entendu parler, et c’est peut-être l’outil par défaut que vous utilisez.Il fonctionne en traçant chaque appel de fonction dans un programme.C’est pourquoi c’est un profiler déterministe : si vous l’exécutez avec les mêmes entrées, il donnera la même sortie.

Par défaut, cProfile mesure le CPU du processus – combien de CPU votre processus a utilisé jusqu’à présent.Vous devriez toujours demander ce que votre profileur mesure, car différentes mesures peuvent détecter différents problèmes.Mesurer le CPU signifie que vous ne pouvez pas détecter la lenteur causée par d’autres causes, comme l’attente d’une réponse d’une requête de base de données.

Bien que cProfile soit toujours disponible dans votre installation Python, il a aussi quelques problèmes – et comme vous le verrez, la plupart du temps, vous ne voulez pas l’utiliser.

Utilisation de cProfile

L’utilisation de cProfile est assez facile.Si vous avez un script que vous exécutez habituellement directement comme suit :

$ python benchmark.py7855 messages/sec

Alors vous pouvez juste préfixer python -m cProfile pour l’exécuter sous le profileur :

Il y a aussi une API de profilage Python, donc vous pouvez profiler des fonctions particulières dans une invite de l’interpréteur Python ou un carnet de notes Jupyter.

Le format de sortie est un tableau, ce qui n’est pas idéal : chaque ligne est un appel de fonction qui s’est exécuté pendant l’intervalle de temps profilé, mais vous ne savez pas comment cet appel de fonction est lié à d’autres appels de fonction.Donc, si vous avez une fonction qui peut être atteinte à partir de plusieurs chemins de code, il peut être difficile de déterminer quel chemin de code était responsable de l’appel de la fonction lente.

Ce que cProfile peut vous dire

Si vous regardez le tableau ci-dessus, vous pouvez voir que :

• _output.py(__call__) a été appelé 50 000 fois. C’est un nombre pair parce que c’est un script de référence qui exécute le même code dans une boucle 10 000 fois.Si vous n’appeliez pas délibérément une fonction de nombreuses fois, cela peut être utile pour repérer un nombre élevé d’appels est utile pour identifier les boucles internes occupées.
• _output.py(send) a utilisé 0,618 seconde de CPU (y compris le temps de CPU des fonctions qu’il a appelées), et 0,045 seconde de CPU (sans inclure les fonctions qu’il a appelées).

En utilisant cette information, vous pouvez repérer les fonctions lentes que vous pouvez optimiser – lentes en ce qui concerne le CPU, en tout cas.

Comment ça marche

cProfile mesure chaque appel de fonction.En particulier, chaque appel de fonction dans l’exécution est enveloppé comme suit :

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

Le profileur enregistre le temps CPU au début et à la fin, et la différence est allouée au compte de cette fonction.

Les problèmes avec cProfile

Bien que cProfile soit toujours disponible dans toute installation de Python, il souffre également de quelques problèmes importants.

Problème n°1 : Frais généraux élevés et résultats faussés

Comme vous pouvez l’imaginer, faire du travail supplémentaire pour chaque appel de fonction a des coûts :

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

Notez combien l’exécution de cProfile est plus lente.Et ce qui est pire, c’est que le ralentissement n’est pas uniforme dans tout votre programme : parce qu’il est lié au nombre d’appels de fonction, les parties de votre code avec plus d’appels de fonction seront plus ralenties.Donc cette surcharge peut fausser les résultats.

Problème n°2 : trop d’informations

Si vous vous souvenez de la sortie cProfile que nous avons vue plus haut, elle comprend une ligne pour chaque fonction qui a été appelée pendant l’exécution du programme.La plupart de ces appels de fonction ne sont pas pertinents pour notre problème de performance : ils s’exécutent rapidement, et seulement une ou deux fois.

Donc, lorsque vous lisez la sortie cProfile, vous avez affaire à beaucoup de bruit supplémentaire qui masque le signal.

Problème n°3 : mesure hors ligne des performances

Bien souvent, votre programme ne sera lent que lorsqu’il est exécuté dans des conditions réelles, avec des entrées réelles.Peut-être que seules des requêtes particulières des utilisateurs ralentissent votre application web, et vous ne savez pas lesquelles.Peut-être que votre programme batch n’est lent qu’avec des données réelles.

Mais cProfile, comme nous l’avons vu, ralentit votre programme de manière assez importante, et donc vous ne voulez probablement pas l’exécuter dans votre environnement de production.Ainsi, alors que la lenteur n’est reproductible qu’en production, cProfile ne vous aide que dans votre environnement de développement.

Problème n°4 : Les performances sont mesurées pour les fonctions uniquement

cProfile peut vous dire « slowfunc() est lent », où il fait la moyenne de toutes les entrées de cette fonction.Et c’est très bien si la fonction est toujours lente.

Mais parfois vous avez un code algorithmique qui n’est lent que pour des entrées spécifiques.Il est tout à fait possible que :

• slowfunc(100) soit rapide.
• slowfunc(0) est lent.

cProfile ne sera pas en mesure de vous dire quelles entrées ont causé la lenteur, ce qui peut rendre plus difficile le diagnostic du problème.

cProfile : Habituellement insuffisant

En raison de ces problèmes, cProfile ne devrait pas être votre outil de performance de choix.Au lieu de cela, nous allons maintenant parler de deux alternatives:

• Pyinstrument résout les problèmes #1 et #2.
• Eliot résout les problèmes #3 et #4.

Pyinstrument : un profileur d’échantillonnage

Pyinstrument résout deux des problèmes que nous avons couverts ci-dessus :

• Il a une surcharge plus faible que cProfile, et il ne déforme pas les résultats.
• Il filtre les appels de fonction non pertinents, donc il y a moins de bruit.

Pyinstrument mesure le temps écoulé de l’horloge murale, pas le temps CPU, donc il peut attraper la lenteur causée par les requêtes réseau, les écritures sur disque, la contention des verrous, et ainsi de suite.

Comment l’utiliser

L’utilisation de Pyinstrument est similaire à cProfile ; il suffit d’ajouter un préfixe à votre script :

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

Notez qu’il a une certaine surcharge, mais pas autant que cProfile-et la surcharge est uniforme.

Pyinstrument a également une API Python, donc vous pouvez l’utiliser pour profiler des morceaux de code particuliers dans un interpréteur interactif Python ou un carnet de notes Jupyter.

La sortie

La sortie de Pyinstrument est un arbre d’appels, mesurant le temps d’horloge murale :

Contrairement au row-per-function de cProfile, Pyinstrument vous donne un arbre d’appels de fonctions, afin que vous puissiez voir le contexte de la lenteur.Une fonction peut apparaître plusieurs fois si la lenteur est causée par plusieurs chemins de code.

En conséquence, la sortie de Pyinstrument est beaucoup plus facile à interpréter, et vous donne une bien meilleure compréhension de la structure de performance de votre programme que la sortie par défaut de cProfile.

Comment ça marche (édition chat)

Imaginez que vous avez un chat.Vous souhaitez savoir comment ce chat passe son temps.

Vous pourriez l’espionner à chaque instant, mais ce serait beaucoup de travail.
Au lieu de cela, vous décidez de prendre des échantillons : toutes les 5 minutes, vous passez votre tête dans la pièce où se trouve le chat, et vous notez ce qu’il fait.

Par exemple :

• 12h00 : Dormir 💤
• 12:05 : Dormir 💤
• 12:10 : Manger 🍲
• 12:15 : Utiliser la litière 💩
• 12:20 : Dormir 💤
• 12 :25 : Dormir 💤
• 12:30 : Dormir 💤

Quelques jours plus tard vous pouvez résumer vos observations:

• 80% : Dormir 💤
• 10% : Manger 🍲
• 9% : Utiliser la litière 💩
• 1% : Fixer longuement les oiseaux par la fenêtre 🐦

Donc, quelle est la précision de ce résumé ? Dans la mesure où votre objectif est de mesurer où le chat a passé la plupart de son temps, il est probablement précis.Et plus les observations (==échantillons) sont fréquentes et plus vous faites d’observations, plus le résumé est précis.

Si votre chat passe la plupart de son temps à dormir, vous vous attendez à ce que la plupart des observations échantillonnées montrent qu’il dort.Et oui, vous manquerez quelques activités rapides et rares – mais pour les besoins de « à quoi le chat a-t-il passé la plupart de son temps », ces activités rapides et rares ne sont pas pertinentes.

Comment ça marche (édition logicielle)

Comme notre chat, Pyinstrument échantillonne le comportement d’un programme Python à intervalles : toutes les 1ms, il vérifie quelle fonction est en cours d’exécution.Cela signifie :

• Si une fonction est cumulativement lente, elle apparaîtra souvent.
• Si une fonction est cumulativement rapide, nous ne la verrons généralement pas du tout.

Cela signifie que notre résumé des performances a moins de bruit : les fonctions qui sont à peine utilisées seront le plus souvent sautées.Mais dans l’ensemble, le résumé est assez précis en ce qui concerne la façon dont le programme a passé son temps, tant que nous avons pris suffisamment d’échantillons.

Eliot : Une bibliothèque de journalisation

Le dernier outil que nous allons couvrir en détail est Eliot, une bibliothèque de journalisation que j’ai écrite.Elle résout les deux autres problèmes que nous avons vus avec cProfile :

• La journalisation peut être utilisée en production.
• La journalisation peut enregistrer les arguments des fonctions.

Comme vous le verrez, Eliot fournit des capacités uniques qui le rendent meilleur pour enregistrer les performances que les bibliothèques de journalisation normales.Ceci étant dit, avec un peu de travail supplémentaire, vous pouvez également obtenir les mêmes avantages avec d’autres bibliothèques de journalisation.

Ajouter la journalisation au code existant

Considérez l’esquisse suivante d’un programme:

Nous pouvons prendre ce code et y ajouter un peu de journalisation:

Spécifiquement, nous faisons deux choses:

1. Dire à Eliot où sortir les messages de journalisation (dans ce cas, un fichier appelé « out.log »).
2. Nous décorons les fonctions avec un décorateur @log_call.Celui-ci enregistrera le fait que la fonction a été appelée, ses arguments et la valeur de retour (ou l’exception levée).

Eliot possède d’autres API plus fines, mais @log_call suffit pour démontrer les avantages de la journalisation.

Sortie d’eliot

Une fois que nous avons exécuté le programme, nous pouvons regarder les journaux en utilisant un outil appelé eliot-tree:

Notez que, un peu comme Pyinstrument, nous regardons un arbre d’actions.J’ai un peu simplifié la sortie – à l’origine pour qu’elle puisse tenir sur une diapositive que j’ai utilisée dans la version talk de cet article – mais même dans un article en prose, cela nous permet de nous concentrer sur l’aspect performance.

Dans Eliot, chaque action a un début et une fin, et peut démarrer d’autres actions – d’où l’arbre résultant.Puisque nous savons quand chaque action enregistrée commence et se termine, nous savons également combien de temps elle a pris.

Dans ce cas, chaque action correspond un-à-un avec un appel de fonction.Et il y a quelques différences par rapport à la sortie de Pyinstrument :

1. Au lieu de combiner plusieurs appels de fonction, vous voyez chaque appel individuel séparément.
2. Vous pouvez voir les arguments et le résultat du retour de chaque appel.
3. Vous pouvez voir le temps écoulé à l’horloge murale de chaque action.

Par exemple, vous pouvez voir que multiplysum() a pris 10 secondes, mais la grande majorité du temps a été passée dans multiply(), avec les entrées de 3 et 4.Vous savez donc immédiatement que pour l’optimisation des performances, vous voulez vous concentrer sur multiply(), et vous avez quelques entrées de départ (3 et 4) pour jouer avec.

Les limites de la journalisation

La journalisation n’est pas suffisante en soi comme source d’informations sur les performances.

Premièrement, vous n’obtenez des informations qu’à partir du code où vous avez explicitement ajouté des appels de journalisation.Un profileur peut s’exécuter sur n’importe quel morceau de code arbitraire sans préparation préalable, mais avec la journalisation, vous devez faire un certain travail à l’avance.

Si vous n’avez pas ajouté de code de journalisation, vous n’obtiendrez aucune information.Eliot rend cela un peu mieux, puisque la structure de l’arbre des actions vous donne un certain sens où le temps a été dépensé, mais ce n’est toujours pas suffisant si la journalisation est trop clairsemée.

Deuxièmement, vous ne pouvez pas ajouter la journalisation partout parce que cela ralentira votre programme.La journalisation n’est pas bon marché-c’est un surcoût plus élevé que cProfile.Donc vous devez l’ajouter judicieusement, dans des points clés où il maximisera l’information qu’il donne sans impacter la performance.

Choisir les bons outils

Alors, quand devez-vous utiliser chaque outil ?

Toujours ajouter la journalisation

Tout programme non trivial a probablement besoin d’une certaine journalisation, ne serait-ce que pour attraper les bogues et les erreurs.Et si vous ajoutez déjà la journalisation, vous pouvez prendre la peine d’enregistrer les informations dont vous avez besoin pour faire du débogage de performance également.

Eliot rend cela plus facile, puisque la journalisation des actions vous donne intrinsèquement le temps écoulé, mais vous pouvez avec un peu de travail supplémentaire faire cela avec n’importe quelle bibliothèque de journalisation.

La journalisation pourrait vous aider à repérer l’endroit spécifique où votre programme est lent, et au moins certaines entrées causant la lenteur, mais c’est souvent insuffisant.L’étape suivante consiste donc à utiliser un profileur, et en particulier un profileur d’échantillonnage comme Pyinstrument :

• Il a une faible surcharge, et surtout ne fausse pas les résultats.
• Il mesure le temps wallclock, donc il ne suppose pas que le CPU est le goulot d’étranglement.
• Il ne sort que les fonctions les plus lentes, en omettant les fonctions rapides non pertinentes.

Utilisez cProfile si vous avez besoin d’une métrique de coût personnalisée

Si jamais vous avez besoin d’écrire un profileur personnalisé, cProfile vous permet de brancher différentes fonctions de coût, ce qui en fait un outil facile pour mesurer des métriques plus inhabituelles.

Vous pouvez mesurer :

• Non-CPU, tout le temps passé à attendre des événements non-CPU.
• Le nombre de changements de contexte volontaires, c’est-à-dire le nombre d’appels système qui prennent beaucoup de temps.
• Les allocations de mémoire.
• Plus largement, tout compteur qui augmente.

TL;DR

Comme bon point de départ sur les outils d’optimisation des performances, je vous suggère de :

1. Loguer les entrées et sorties clés, et le temps écoulé des actions clés, en utilisant Eliot ou une autre bibliothèque de logging.
2. Utiliser Pyinstrument – ou un autre profileur d’échantillonnage – comme profileur par défaut.
3. Utiliser cProfile quand si vous avez besoin d’un profileur personnalisé.