Scrivere programmi è divertente, ma renderli veloci può essere una sofferenza. I programmi Python non fanno eccezione, ma la toolchain di base per la profilazione non è in realtà così complicata da usare. Qui, vorrei mostrarvi come potete rapidamente profilare e analizzare il vostro codice Python per trovare quale parte del codice dovreste ottimizzare.
Profilare un programma Python significa fare un’analisi dinamica che misura il tempo di esecuzione del programma e tutto ciò che lo compone. Questo significa misurare il tempo trascorso in ciascuna delle sue funzioni. Questo vi darà dati su dove il vostro programma sta spendendo tempo, e quale area potrebbe valere la pena di ottimizzare.
È un esercizio molto interessante. Molte persone si concentrano sulle ottimizzazioni locali, come ad esempio determinare quale delle funzioni Python range o xrange sarà più veloce. Si scopre che sapere quale sia più veloce potrebbe non essere mai un problema nel vostro programma, e che il tempo guadagnato da una delle funzioni di cui sopra potrebbe non valere il tempo che passate a fare ricerche o a discuterne con il vostro collega.
Tentare di ottimizzare alla cieca un programma senza misurare dove sta effettivamente spendendo il suo tempo è un esercizio inutile. Seguire solo il vostro istinto non è sempre sufficiente.
Ci sono molti tipi di profiling, come ci sono molte cose che potete misurare. In questo esercizio, ci concentreremo sulla profilazione dell’utilizzo della CPU, cioè il tempo trascorso da ogni funzione nell’esecuzione delle istruzioni. Ovviamente, potremmo fare molti altri tipi di profilazione e ottimizzazioni, come la profilazione della memoria che misurerebbe la memoria usata da ogni pezzo di codice – qualcosa di cui parlo in The Hacker’s Guide to Python.
cProfile
Da Python 2.5, Python fornisce un modulo C chiamato cProfile che ha un overhead ragionevole e offre un set di funzionalità abbastanza buono. L’uso di base è il seguente:
Sebbene si possa anche eseguire uno script con esso, che risulta essere comodo:
Questo stampa tutte le funzioni chiamate, con il tempo trascorso in ciascuna e il numero di volte che sono state chiamate.
Visualizzazione avanzata con KCacheGrind
Pur essendo utile, il formato di output è molto semplice e non rende facile la conoscenza di programmi completi. Per una visualizzazione più avanzata, sfrutto KCacheGrind. Se avete fatto un po’ di programmazione e profilazione in C negli ultimi anni, potreste averlo usato in quanto è principalmente progettato come front-end per i call-graph generati da Valgrind.
Per usarlo, dovete generare un file di risultato cProfile, poi convertirlo in formato KCacheGrind. Per farlo, io uso pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprofE la finestra di KCacheGrind appare magicamente!
Caso concreto: Ottimizzazione di Carbonara
Ero curioso delle prestazioni di Carbonara, la piccola libreria di serie temporali che ho scritto per Gnocchi. Ho deciso di fare un po’ di profiling di base per vedere se c’era qualche evidente ottimizzazione da fare.
Per profilare un programma, è necessario eseguirlo. Ma eseguire l’intero programma in modalità di profilazione può generare un sacco di dati che non ti interessano, e aggiunge rumore a ciò che stai cercando di capire. Dato che Gnocchi ha migliaia di test unitari e alcuni per Carbonara stessa, ho deciso di profilare il codice usato da questi test unitari, dato che è un buon riflesso delle caratteristiche di base della libreria.
Nota che questa è una buona strategia per un curioso e ingenuo first-pass profiling.
Non c’è modo che tu possa essere sicuro che gli hotspot che vedrai nei test unitari siano gli hotspot reali che incontrerai in produzione. Pertanto, una profilazione in condizioni e con uno scenario che imita ciò che si vede in produzione è spesso una necessità se avete bisogno di spingere ulteriormente l’ottimizzazione del vostro programma e volete ottenere un guadagno percepibile e prezioso.
Ho attivato cProfile usando il metodo descritto sopra, creando un oggetto cProfile.Profile intorno ai miei test (in realtà ho iniziato a implementarlo in testtools). Ho poi eseguito KCacheGrind come descritto sopra. Usando KCacheGrind, ho generato i seguenti dati.
Il test che ho profilato qui si chiama test_fetch ed è abbastanza facile da capire: mette i dati in un oggetto timeserie, e poi recupera il risultato aggregato. L’elenco qui sopra mostra che l’88% dei tick sono spesi in set_values (44 tick su 50). Questa funzione è usata per inserire i valori nella timeserie, non per recuperare i valori. Ciò significa che è molto lento per inserire i dati, e piuttosto veloce per recuperarli.
Leggendo il resto della lista si nota che diverse funzioni condividono il resto dei tick, update, _first_block_timestamp, _truncate, _resample, ecc. Alcune delle funzioni della lista non fanno parte di Carbonara, quindi non ha senso cercare di ottimizzarle. L’unica cosa che può essere ottimizzata è, a volte, il numero di volte che vengono chiamate.
Il grafico delle chiamate mi dà un po’ più di informazioni su cosa sta succedendo qui. Usando le mie conoscenze su come funziona Carbonara, non penso che l’intero stack a sinistra per _first_block_timestamp abbia molto senso. Questa funzione dovrebbe trovare il primo timestamp per un aggregato, ad esempio con un timestamp di 13:34:45 e un periodo di 5 minuti, la funzione dovrebbe restituire 13:30:00. Il modo in cui funziona attualmente è chiamando la funzione resample di Pandas su una timeserie con un solo elemento, ma questo sembra essere molto lento. Infatti, attualmente questa funzione rappresenta il 25% del tempo speso da set_values (11 tick su 44).
Fortunatamente, ho recentemente aggiunto una piccola funzione chiamata _round_timestamp che fa esattamente ciò di cui _first_block_timestamp ha bisogno senza chiamare alcuna funzione Pandas, quindi niente resample. Così ho finito per riscrivere quella funzione in questo modo:
E poi ho rieseguito lo stesso identico test per confrontare l’output di cProfile.
L’elenco delle funzioni sembra abbastanza diverso questa volta. Il numero di tempo impiegato da set_values è sceso dall’88% al 71%.
Lo stack delle chiamate per set_values lo mostra abbastanza bene: non possiamo nemmeno vedere la funzione _first_block_timestamp perché è così veloce che è totalmente scomparsa dal display. Ora viene considerata insignificante dal profiler.
Quindi abbiamo appena velocizzato l’intero processo di inserimento dei valori in Carbonara di un bel 25% in pochi minuti. Non male per un primo passaggio ingenuo, vero?
Se volete saperne di più, ho scritto un intero capitolo sull’ottimizzazione del codice in Scaling Python. Date un’occhiata!