Il modulo profile fornisce le API per collezionare e analizzare dati statistici sul modo nel quale il sorgente Pyhton utilizza le risorse del processore.

Eseguire il Profilatore

Il punto più basico da cui partire nel modulo profile è run(). Riceve una singola istruzione come argomento, e crea un report con il tempo trascorso per l'esecuzione delle varie righe di codice mentre viene eseguita l'istruzione.

# profile_fibonacci_raw.py

import profile


def fib(n):
    # da literateprograms.org
    # http://bit.ly/hlOQ5m
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n - 1) + fib(n - 2)


def fib_seq(n):
    seq = []
    if n > 0:
        seq.extend(fib_seq(n - 1))
    seq.append(fib(n))
    return seq


profile.run('print(fib_seq(20)); print()')

Questa funzione ricorsiva per un calcolatore di sequenze di Fibonacci è particolarmente utile per la dimostrazione di profile visto che le prestazioni possono essere migliorate in modo significativo. Il formato standard del report mostra un sommario seguito dai dettagli per ciascuna funzione eseguita.

$ python3 profile_fibonacci_raw.py

[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]

         57359 function calls (69 primitive calls) in 0.128 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.127    0.127 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        1    0.000    0.000    0.127    0.127 <string>:1(<module>)
        1    0.000    0.000    0.128    0.128 profile:0(print(fib_seq(20)); print())
        0    0.000             0.000          profile:0(profiler)
     21/1    0.000    0.000    0.127    0.127 profile_fibonacci_raw.py:17(fib_seq)
 57291/21    0.126    0.000    0.126    0.006 profile_fibonacci_raw.py:6(fib)

La versione grezza richiede 57359 chiamate di funzione separate e impiega per l'esecuzione più o meno 0.100 secondi. Il fatto che si siano solo 69 chiamate primitive dice che la vasta maggioranza delle 57 mila e passa chiamate sono ricorsive. Il dettaglio sul dove il tempo è stato speso è per funzione nel listato che mostra il numero di chiamate, il tempo totale trascorso nella funzione, il tempo per chiamata (tottime/ncalls), il tempo cumulativo trascorso nella funzione e il rapporto tra tempo cumulativo e chiamate primitive.

Meno che sorprendentemente, la maggior parte del tempo viene speso chiamando fib() ripetutamente. L'aggiunta di un decoratore di cache riduce il numero di chiamate ricorsive, ed ha un grosso impatto sulle prestazioni di questa funzione.

# profile_fibonacci_memoized.py

import functools
import profile


@functools.lru_cache(maxsize=None)
def fib(n):
    # da literateprograms.org
    # http://bit.ly/hlOQ5m
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n - 1) + fib(n - 2)


def fib_seq(n):
    seq = []
    if n > 0:
        seq.extend(fib_seq(n - 1))
    seq.append(fib(n))
    return seq


if __name__ == '__main__':
    profile.run('print(fib_seq(20)); print()')

Trattenendo in memoria il valore di Fibonacci a ogni livello, la maggior parte della ricorsione viene evitata e l'esecuzione si riduce ad 89 chiamate che richiedono solo 0.001 secondi. Il conteggio di ncalls per fib() mostra che non viene mai chiamata ricorsivamente.

$ python3 profile_fibonacci_memoized.py

[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]

         89 function calls (69 primitive calls) in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.000    0.000 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.001    0.001 profile:0(print(fib_seq(20)); print())
        0    0.000             0.000          profile:0(profiler)
     21/1    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:19(fib_seq)
       21    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:7(fib)

Esecuzione in un Contesto

Talvolta, invece che costruire una espressione complessa per run(), è più facile costruire una espressione semplice e passarle parametri tramite un contesto, usando runctx().

# profile_runctx.py

import profile
from profile_fibonacci_memoized import fib, fib_seq

if __name__ == '__main__':
    profile.runctx(
        'print(fib_seq(n)); print()',
        globals(),
        {'n': 20},
    )

In questo esempio, il valore di n è passato tramite la variabile locale di contesto invece che essere direttamente incorporata nell'istruzione passata a runctx().

$ python3 profile_runctx.py

[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]

         89 function calls (69 primitive calls) in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.000    0.000 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.001    0.001 profile:0(print(fib_seq(n)); print())
        0    0.000             0.000          profile:0(profiler)
     21/1    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:19(fib_seq)
       21    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:7(fib)

pstats: Salvare e Lavorare con le Statistiche

Il report standard creato dalle funzioni in profile non è molto flessibile. Possono comunque essere prodotti report personalizzati salvato la profilatura grezza dei dati in uscita da run() e runctx(), quindi elaborandoli separatamente con la classe pstats.Stats.

Questo esempio esegue parecchie iterazioni per lo stesso test e combina i risultati.

# profile_stats.py

import cProfile as profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq

# Crea 5 insiemi di statistiche
for i in range(5):
    filename = 'profile_stats_{}.stats'.format(i)
    profile.run('print({}, fib_seq(20))'.format(i), filename)

# Legge i 5 file di statistica in un singolo oggetto
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))

# Toglie i nomi delle directory dai file per il report
stats.strip_dirs()

# Ordina le statistiche per tempo cumulativo trascorso
# nella funzione
stats.sort_stats('cumulative')

stats.print_stats()

Il report in uscita è in ordine discendente per tempo cumulativo trascorso nella funzione e i nomi di directory sono rimossi dai nomi dei file stampati per risparmiare spazio orizzontale nella pagina.

$ python3 profile_stats.py

0 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
1 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
2 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
3 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
4 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
Thu Jun  3 09:15:32 2021    profile_stats_0.stats
Thu Jun  3 09:15:32 2021    profile_stats_1.stats
Thu Jun  3 09:15:32 2021    profile_stats_2.stats
Thu Jun  3 09:15:32 2021    profile_stats_3.stats
Thu Jun  3 09:15:32 2021    profile_stats_4.stats

         351 function calls (251 primitive calls) in 0.001 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5    0.000    0.000    0.001    0.000 {built-in method builtins.exec}
        5    0.000    0.000    0.000    0.000 <string>:1(<module>)
    105/5    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:19(fib_seq)
        5    0.000    0.000    0.000    0.000 {built-in method builtins.print}
      100    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
      105    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
       21    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:7(fib)
        5    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Limitare il Contenuto del Report

Il risultato può essere circoscritto per funzione. Questa versione mostra solo le informazioni circa le prestazioni per fib() e fib_seq() usando una espressione regolare per trovare corrispondenza con i valori desiderati per filename:lineno(function).

# profile_stats_restricted.py

import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq

# Legge tutti e 5 i file di statistica in un singolo oggetto
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))
stats.strip_dirs()
stats.sort_stats('cumulative')

# limita l'output alle righe che contengono  "(fib"
stats.print_stats('\(fib')

L'espressione regolare include una parentesi sinistra letterale (() per trovare corrispondenza con la porzione del nome di funzione del valore.

$ python3 profile_stats_restricted.py

Thu Jun  3 09:15:32 2021    profile_stats_0.stats
Thu Jun  3 09:15:32 2021    profile_stats_1.stats
Thu Jun  3 09:15:32 2021    profile_stats_2.stats
Thu Jun  3 09:15:32 2021    profile_stats_3.stats
Thu Jun  3 09:15:32 2021    profile_stats_4.stats

         351 function calls (251 primitive calls) in 0.001 seconds

   Ordered by: cumulative time
   List reduced from 8 to 2 due to restriction <'\\(fib'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    105/5    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:19(fib_seq)
       21    0.000    0.000    0.000    0.000 profile_fibonacci_memoized.py:7(fib)

Grafi di Chiamante e Chiamato

Stats include anche metodi per stampare i chiamanti e le chiamate di funzioni.

# profile_stats_callers.py

import cProfile as profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq

# Legge tutti e 5 i file di statistica in un singolo oggetto
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))
stats.strip_dirs()
stats.sort_stats('cumulative')

print('CHIAMANTI IN ENTRATA:')
stats.print_callers('\(fib')

print('CHIAMATE IN USCITA  :')
stats.print_callees('\(fib')

Gli argomenti per print_callers() e print_callees() funzionano allo stesso modo degli argomenti di restrizione per print_stats(). Il risultato mostra il chiamante, il chiamato, il numero di chiamate e il tempo cumulativo.

$ python3 profile_stats_callers.py

CHIAMANTI IN ENTRATA:
   Ordered by: cumulative time
   List reduced from 8 to 2 due to restriction <'\\(fib'>

Function                                   was called by...
                                               ncalls  tottime  cumtime
profile_fibonacci_memoized.py:19(fib_seq)  <-       5    0.000    0.000  <string>:1(<module>)
                                                100/5    0.000    0.000  profile_fibonacci_memoized.py:19(fib_seq)
profile_fibonacci_memoized.py:7(fib)       <-      21    0.000    0.000  profile_fibonacci_memoized.py:19(fib_seq)


CHIAMATE IN USCITA  :
   Ordered by: cumulative time
   List reduced from 8 to 2 due to restriction <'\\(fib'>

Function                                   called...
                                               ncalls  tottime  cumtime
profile_fibonacci_memoized.py:19(fib_seq)  ->      21    0.000    0.000  profile_fibonacci_memoized.py:7(fib)
                                                100/5    0.000    0.000  profile_fibonacci_memoized.py:19(fib_seq)
                                                  105    0.000    0.000  {method 'append' of 'list' objects}
                                                  100    0.000    0.000  {method 'extend' of 'list' objects}
profile_fibonacci_memoized.py:7(fib)       -> 

.