Comment puis-je profiler le code Python ligne par ligne?

116

J'utilise cProfile pour profiler mon code et cela fonctionne très bien. J'utilise également gprof2dot.py pour visualiser les résultats (le rend un peu plus clair).

Cependant, cProfile (et la plupart des autres profileurs Python que j'ai vus jusqu'à présent) semblent uniquement profiler au niveau de l'appel de fonction. Cela crée de la confusion lorsque certaines fonctions sont appelées à partir d'endroits différents - je n'ai aucune idée si l'appel n ° 1 ou l'appel n ° 2 prend la majorité du temps. Cela devient encore pire lorsque la fonction en question a six niveaux de profondeur, appelée depuis sept autres endroits.

Comment obtenir un profilage ligne par ligne?

Au lieu de cela:

function #12, total time: 2.0s

J'aimerais voir quelque chose comme ça:

function #12 (called from somefile.py:102) 0.5s
function #12 (called from main.py:12) 1.5s

cProfile montre combien de temps total "transfère" au parent, mais encore une fois cette connexion est perdue quand vous avez un tas de couches et d'appels interconnectés.

Idéalement, j'aimerais avoir une interface graphique qui analyserait les données, puis me montrerait mon fichier source avec un temps total donné à chaque ligne. Quelque chose comme ça:

main.py:

a = 1 # 0.0s
result = func(a) # 0.4s
c = 1000 # 0.0s
result = func(c) # 5.0s

Ensuite, je serais capable de cliquer sur le deuxième appel "func (c)" pour voir ce qui prend du temps dans cet appel, indépendamment de l'appel "func (a)".

Cela a-t-il du sens? Existe-t-il une bibliothèque de profilage qui collecte ce type d'informations? Y a-t-il un outil génial que j'ai manqué?

singes-fusées
la source
2
Je suppose que cela vous intéresserait pstats.print_callers. Un exemple est ici .
Muhammad Alkarouri
Muhammad, c'est vraiment utile! Au moins, il corrige un problème: séparer les appels de fonction en fonction de l'origine. Je pense que la réponse de Joe Kington est plus proche de mon objectif, mais print_callers () me met définitivement à mi-chemin. Merci!
rocketmonkeys

Réponses:

120

Je crois que c'est à cela que sert le line_profiler de Robert Kern . Depuis le lien:

File: pystone.py
Function: Proc2 at line 149
Total time: 0.606656 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   149                                           @profile
   150                                           def Proc2(IntParIO):
   151     50000        82003      1.6     13.5      IntLoc = IntParIO + 10
   152     50000        63162      1.3     10.4      while 1:
   153     50000        69065      1.4     11.4          if Char1Glob == 'A':
   154     50000        66354      1.3     10.9              IntLoc = IntLoc - 1
   155     50000        67263      1.3     11.1              IntParIO = IntLoc - IntGlob
   156     50000        65494      1.3     10.8              EnumLoc = Ident1
   157     50000        68001      1.4     11.2          if EnumLoc == Ident1:
   158     50000        63739      1.3     10.5              break
   159     50000        61575      1.2     10.1      return IntParIO

J'espère que cela pourra aider!

Joe Kington
la source
10
Line_profiler fonctionne-t-il avec Python 3? Je n'ai pas pu obtenir d'informations à ce sujet.
user1251007
3
line_profiler n'affiche pas les hits et le temps pour moi. Quelqu'un peut-il me dire pourquoi? Et comment résoudre?
I159
6
Voici le décorateur que j'ai écrit: gist.github.com/kylegibson/6583590 . Si vous exécutez nosetests, assurez-vous d'utiliser l'option -s pour que stdout soit imprimé immédiatement.
Kyle Gibson
5
à quoi ressemble le script python qui produit cette sortie? import line_profiler;puis ?
Zhubarb
10
quelqu'un peut-il montrer comment utiliser réellement cette bibliothèque? Le readme enseigne comment installer et répond à diverses FAQ, mais ne mentionne pas comment l'utiliser après une installation pip ..
cryanbhu
47

Vous pouvez également utiliser pprofile ( pypi ). Si vous souhaitez profiler l'ensemble de l'exécution, cela ne nécessite pas de modification du code source. Vous pouvez également profiler un sous-ensemble d'un programme plus vaste de deux manières:

  • basculer le profilage lorsque vous atteignez un point spécifique du code, tel que:

    import pprofile
    profiler = pprofile.Profile()
    with profiler:
        some_code
    # Process profile content: generate a cachegrind file and send it to user.
    
    # You can also write the result to the console:
    profiler.print_stats()
    
    # Or to a file:
    profiler.dump_stats("/tmp/profiler_stats.txt")
  • basculer le profilage de manière asynchrone à partir de la pile d'appels (nécessite un moyen de déclencher ce code dans l'application considérée, par exemple un gestionnaire de signal ou un thread de travail disponible) en utilisant le profilage statistique:

    import pprofile
    profiler = pprofile.StatisticalProfile()
    statistical_profiler_thread = pprofile.StatisticalThread(
        profiler=profiler,
    )
    with statistical_profiler_thread:
        sleep(n)
    # Likewise, process profile content

Le format de sortie des annotations de code ressemble beaucoup au profileur de ligne:

$ pprofile --threads 0 demo/threads.py
Command line: ['demo/threads.py']
Total duration: 1.00573s
File: demo/threads.py
File duration: 1.00168s (99.60%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         2|  3.21865e-05|  1.60933e-05|  0.00%|import threading
     2|         1|  5.96046e-06|  5.96046e-06|  0.00%|import time
     3|         0|            0|            0|  0.00%|
     4|         2|   1.5974e-05|  7.98702e-06|  0.00%|def func():
     5|         1|      1.00111|      1.00111| 99.54%|  time.sleep(1)
     6|         0|            0|            0|  0.00%|
     7|         2|  2.00272e-05|  1.00136e-05|  0.00%|def func2():
     8|         1|  1.69277e-05|  1.69277e-05|  0.00%|  pass
     9|         0|            0|            0|  0.00%|
    10|         1|  1.81198e-05|  1.81198e-05|  0.00%|t1 = threading.Thread(target=func)
(call)|         1|  0.000610828|  0.000610828|  0.06%|# /usr/lib/python2.7/threading.py:436 __init__
    11|         1|  1.52588e-05|  1.52588e-05|  0.00%|t2 = threading.Thread(target=func)
(call)|         1|  0.000438929|  0.000438929|  0.04%|# /usr/lib/python2.7/threading.py:436 __init__
    12|         1|  4.79221e-05|  4.79221e-05|  0.00%|t1.start()
(call)|         1|  0.000843048|  0.000843048|  0.08%|# /usr/lib/python2.7/threading.py:485 start
    13|         1|  6.48499e-05|  6.48499e-05|  0.01%|t2.start()
(call)|         1|   0.00115609|   0.00115609|  0.11%|# /usr/lib/python2.7/threading.py:485 start
    14|         1|  0.000205994|  0.000205994|  0.02%|(func(), func2())
(call)|         1|      1.00112|      1.00112| 99.54%|# demo/threads.py:4 func
(call)|         1|  3.09944e-05|  3.09944e-05|  0.00%|# demo/threads.py:7 func2
    15|         1|  7.62939e-05|  7.62939e-05|  0.01%|t1.join()
(call)|         1|  0.000423908|  0.000423908|  0.04%|# /usr/lib/python2.7/threading.py:653 join
    16|         1|  5.26905e-05|  5.26905e-05|  0.01%|t2.join()
(call)|         1|  0.000320196|  0.000320196|  0.03%|# /usr/lib/python2.7/threading.py:653 join

Notez que parce que pprofile ne repose pas sur la modification du code, il peut profiler les instructions de module de niveau supérieur, ce qui permet de profiler le temps de démarrage du programme (combien de temps il faut pour importer les modules, initialiser les globaux, ...).

Il peut générer une sortie au format cachegrind, vous pouvez donc utiliser kcachegrind pour parcourir facilement des résultats volumineux.

Divulgation: Je suis auteur de pprofile.

vpelletier
la source
1
+1 Merci pour votre contribution. Ça a l'air bien fait. J'ai une perspective un peu différente - mesurer le temps inclusif pris par les déclarations et les fonctions est un objectif. Découvrir ce qui peut être fait pour accélérer le code est un objectif différent. La différence devient douloureusement évidente à mesure que le code devient volumineux - comme 10 ^ 6 lignes de code. Le code peut perdre de gros pourcentages de temps. La façon dont je trouve cela est de prendre un petit nombre d'échantillons très détaillés et de les examiner avec un œil humain - pas de résumer. Le problème est exposé par la fraction de temps qu'il perd.
Mike Dunlavey
1
Vous avez raison, je n'ai pas mentionné l'utilisation de pprofile quand on veut profiler un sous-ensemble plus petit. J'ai édité mon message pour en ajouter des exemples.
vpelletier le
3
C'est exactement ce que je recherchais: non intrusif et extensif.
egpbos
1
Bel outil, mais il tourne plusieurs fois plus lentement que le code d'origine.
rominf
4

Vous pouvez prendre l'aide du package line_profiler pour cela

1. Installez d'abord le package:

    pip install line_profiler

2. Utilisez la commande magique pour charger le package dans votre environnement python / notebook

    %load_ext line_profiler

3. Si vous souhaitez profiler les codes d'une fonction,
procédez comme suit:

    %lprun -f demo_func demo_func(arg1, arg2)

vous obtiendrez une belle sortie formatée avec tous les détails si vous suivez ces étapes :)

Line #      Hits      Time    Per Hit   % Time  Line Contents
 1                                           def demo_func(a,b):
 2         1        248.0    248.0     64.8      print(a+b)
 3         1         40.0     40.0     10.4      print(a)
 4         1         94.0     94.0     24.5      print(a*b)
 5         1          1.0      1.0      0.3      return a/b
Sateesh
la source
4

Juste pour améliorer l » Kington @ Joe réponse ci - dessus mentionnée .

Pour Python 3.x , utilisez line_profiler :


Installation:

pip install line_profiler

Usage:

Supposons que vous ayez le programme main.pyet en son sein, des fonctions fun_a()et fun_b()que vous vouliez profiler par rapport au temps; vous devrez utiliser le décorateur @profilejuste avant les définitions de fonction. Par exemple,

@profile
def fun_a():
    #do something

@profile
def fun_b():
    #do something more

if __name__ == '__main__':
    fun_a()
    fun_b()

Le programme peut être profilé en exécutant la commande shell:

$ kernprof -l -v main.py

Les arguments peuvent être récupérés en utilisant $ kernprof -h

Usage: kernprof [-s setupfile] [-o output_file_path] scriptfile [arg] ...

Options:
  --version             show program's version number and exit
  -h, --help            show this help message and exit
  -l, --line-by-line    Use the line-by-line profiler from the line_profiler
                        module instead of Profile. Implies --builtin.
  -b, --builtin         Put 'profile' in the builtins. Use 'profile.enable()'
                        and 'profile.disable()' in your code to turn it on and
                        off, or '@profile' to decorate a single function, or
                        'with profile:' to profile a single section of code.
  -o OUTFILE, --outfile=OUTFILE
                        Save stats to <outfile>
  -s SETUP, --setup=SETUP
                        Code to execute before the code to profile
  -v, --view            View the results of the profile in addition to saving
                        it.

Les résultats seront imprimés sur la console sous la forme:

Total time: 17.6699 s
File: main.py
Function: fun_a at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    5                                           @profile
    6                                           def fun_a():
...

EDIT: Les résultats des profileurs peuvent être analysés à l'aide du package TAMPPA . En l'utilisant, nous pouvons obtenir des graphiques souhaités ligne par ligne comme terrain

Pe Dro
la source
1

PyVmMonitor a une vue en direct qui peut vous y aider (vous pouvez vous connecter à un programme en cours d'exécution et en obtenir des statistiques).

Voir: http://www.pyvmmonitor.com/

Fabio Zadrozny
la source