Oltre il cProfile: Scegliere lo strumento giusto per l’ottimizzazione delle prestazioni

Nota: Questo articolo è basato su un discorso che ho tenuto a PyGotham 2019. Puoi guardare il video qui.

Il tuo programma Python è troppo lento.Forse la tua applicazione web non riesce a tenere il passo, o certe query richiedono molto tempo.Forse hai un programma batch che impiega ore o addirittura giorni per essere eseguito.

Come puoi accelerare?

Il processo di base che probabilmente seguirai è:

1. Scegli lo strumento giusto per misurare la velocità.
2. Usa lo strumento per capire il collo di bottiglia.
3. Fissare il collo di bottiglia.

Questo articolo si concentrerà sul primo passo: scegliere lo strumento giusto.E in particolare, coprirà:

• cProfile: Il profilatore deterministico della libreria standard Python.
• Pyinstrument: Un profilatore di campionamento.
• Eliot: Una libreria di log.

Non entrerò in una quantità enorme di dettagli su come usare questi strumenti, perché l’obiettivo è quello di aiutarvi a scegliere quello giusto. Ma spiegherò cosa fanno questi strumenti e quando e perché dovreste sceglierne uno piuttosto che un altro.

cProfile: Un profilatore deterministico

Il profilatore cProfile è integrato in Python, quindi probabilmente ne avrete sentito parlare, e potrebbe essere lo strumento predefinito che usate.Funziona tracciando ogni chiamata di funzione in un programma.Ecco perché è un profilatore deterministico: se lo eseguite con gli stessi input darà lo stesso output.

Di default cProfile misura la CPU del processo, quanta CPU ha usato finora il vostro processo.Dovreste sempre chiedere cosa sta misurando il vostro profiler, perché misure diverse possono rilevare problemi diversi.Misurare la CPU significa che non potete rilevare la lentezza causata da altre cause, come l’attesa di una risposta da una query al database.

Mentre cProfile è sempre disponibile nella vostra installazione di Python, ha anche alcuni problemi-e come vedrete, la maggior parte delle volte non volete usarlo.

Usare cProfile

Usare cProfile è abbastanza facile.Se hai uno script che di solito esegui direttamente come questo:

$ python benchmark.py7855 messages/sec

Poi puoi semplicemente anteporre il prefisso python -m cProfile per eseguirlo sotto il profilatore:

C’è anche un’API di profilazione Python, così puoi profilare particolari funzioni in un prompt dell’interprete Python o in un notebook Jupyter.

Il formato di output è una tabella, che non è l’ideale: ogni riga è una chiamata di funzione che è stata eseguita durante l’intervallo di tempo profilato, ma non si sa come quella chiamata di funzione è collegata ad altre chiamate di funzione.Quindi se avete una funzione che può essere raggiunta da più percorsi di codice, può essere difficile capire quale percorso di codice è stato responsabile della chiamata della funzione lenta.

Cosa può dirvi cProfile

Se guardate la tabella sopra, potete vedere che:

• _output.py(__call__) è stato chiamato 50.000 volte. È un numero pari perché questo è uno script di benchmark che esegue lo stesso codice in un ciclo 10.000 volte.Se non stavate deliberatamente chiamando una funzione molte volte, questo può essere utile per individuare un alto numero di chiamate è utile per identificare i loop interni occupati.
• _output.py(send) ha usato 0,618 secondi di CPU (compreso il tempo di CPU delle funzioni che ha chiamato), e 0,045 secondi di CPU (non comprese le funzioni che ha chiamato).

Utilizzando queste informazioni puoi individuare le funzioni lente che puoi ottimizzare – lente per quanto riguarda la CPU, comunque.

Come funziona

cProfile misura ogni singola chiamata di funzione.In particolare, ogni chiamata di funzione nella corsa viene impacchettata così:

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

Il profiler registra il tempo della CPU all’inizio e alla fine, e la differenza viene assegnata al conto di quella funzione.

I problemi con cProfile

Mentre cProfile è sempre disponibile in qualsiasi installazione di Python, soffre anche di alcuni problemi significativi.

Problema #1: Elevato overhead e risultati distorti

Come potete immaginare, fare del lavoro extra per ogni chiamata di funzione ha dei costi:

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

Nota quanto sia più lenta l’esecuzione di cProfile.E quel che è peggio, il rallentamento non è uniforme in tutto il vostro programma: poiché è legato al numero di chiamate di funzione, le parti del vostro codice con più chiamate di funzione saranno più rallentate.

Problema #2: Troppe informazioni

Se vi ricordate l’output di cProfile che abbiamo visto sopra, include una riga per ogni singola funzione che è stata chiamata durante l’esecuzione del programma.La maggior parte di queste chiamate di funzione sono irrilevanti per il nostro problema di performance: vengono eseguite velocemente, e solo una o due volte.

Quindi quando state leggendo l’output di cProfile, avete a che fare con un sacco di rumore extra che maschera il segnale.

Problema #3: Misura offline delle prestazioni

Quasi spesso il vostro programma sarà lento solo quando viene eseguito in condizioni reali, con input reali.Forse solo particolari query degli utenti rallentano la vostra applicazione web, e non sapete quali query.Forse il vostro programma batch è lento solo con dati reali.

Ma cProfile, come abbiamo visto, rallenta parecchio il vostro programma, e quindi probabilmente non volete eseguirlo nel vostro ambiente di produzione.Quindi, mentre la lentezza è riproducibile solo in produzione, cProfile vi aiuta solo nel vostro ambiente di sviluppo.

Problema #4: Le prestazioni sono misurate solo per le funzioni

cProfile può dirvi “slowfunc() è lento”, dove fa una media di tutti gli input di quella funzione.E questo va bene se la funzione è sempre lenta.

Ma a volte avete del codice algoritmico che è lento solo per input specifici.È abbastanza possibile che:

• slowfunc(100) sia veloce.
• slowfunc(0) è lento.

cProfile non sarà in grado di dirvi quali input hanno causato la lentezza, il che può rendere più difficile la diagnosi del problema.

cProfile: Solitamente insufficiente

A causa di questi problemi, cProfile non dovrebbe essere il vostro strumento di performance preferito.Invece, ora parleremo di due alternative:

• Pyinstrument risolve i problemi #1 e #2.
• Eliot risolve i problemi #3 e #4.

Pyinstrument: un profiler di campionamento

Pyinstrument risolve due dei problemi che abbiamo trattato sopra:

• Ha un overhead inferiore a cProfile, e non distorce i risultati.
• Filtra le chiamate di funzioni irrilevanti, quindi c’è meno rumore.

Pyinstrument misura il tempo trascorso nel wallclock, non il tempo della CPU, quindi può catturare la lentezza causata da richieste di rete, scritture su disco, contesa dei lock e così via.

Come si usa

Utilizzare Pyinstrument è simile a cProfile; basta aggiungere un prefisso al tuo script:

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

Nota che ha un po’ di overhead, ma non quanto cProfile-e l’overhead è uniforme.

Pyinstrument ha anche un’API Python, quindi potete usarlo per profilare particolari pezzi di codice in un interprete interattivo Python o in un notebook Jupyter.

L’output

L’output di Pyinstrument è un albero di chiamate, che misura il tempo dell’orologio a muro:

A differenza della riga per funzione di cProfile, Pyinstrument vi dà un albero di chiamate di funzione, così potete vedere il contesto della lentezza.

Come risultato, l’output di Pyinstrument è molto più facile da interpretare, e vi dà una migliore comprensione della struttura delle prestazioni del vostro programma rispetto all’output di default di cProfile.

Come funziona (cat edition)

Immaginate di avere un gatto e volete sapere come passa il suo tempo.

Si potrebbe spiare ogni suo momento, ma sarebbe un sacco di lavoro.Così invece si decide di prendere dei campioni: ogni 5 minuti si infila la testa nella stanza dove si trova il gatto, e si scrive cosa sta facendo.

Per esempio:

• 12:00: Dormire 💤
• 12:05: Dormire 💤
• 12:10: Mangiare 🍲
• 12:15: Usare la lettiera 💩
• 12:20: Dormire 💤
• 12:25: Dormire 💤
• 12:30: Dormire 💤

Alcuni giorni dopo puoi riassumere le tue osservazioni:

• 80%: Dormire 💤
• 10%: Mangiare 🍲
• 9%: Usare la lettiera 💩
• 1%: Fissare gli uccelli attraverso la finestra 🐦

Quanto è accurato questo riassunto? Nella misura in cui il tuo obiettivo è quello di misurare dove il gatto ha passato la maggior parte del suo tempo, è probabilmente accurato, e più frequenti sono le osservazioni (==campioni) e più osservazioni fai, più accurato è il riassunto.

Se il gatto passa la maggior parte del suo tempo a dormire, ci si aspetta che la maggior parte delle osservazioni campionate mostri che sta dormendo.E sì, si perderanno alcune attività rapide e rare – ma ai fini del “a cosa ha dedicato la maggior parte del suo tempo il gatto” queste attività rapide e rare sono irrilevanti.

Come funziona (edizione software)

Proprio come il nostro gatto, Pyinstrument campiona il comportamento di un programma Python a intervalli: ogni 1ms controlla quale funzione è attualmente in esecuzione.Questo significa:

• Se una funzione è cumulativamente lenta, apparirà spesso.
• Se una funzione è cumulativamente veloce, di solito non la vedremo affatto.

Questo significa che il nostro riepilogo delle prestazioni ha meno rumore: le funzioni che sono a malapena usate saranno per lo più saltate.Ma nel complesso il riepilogo è abbastanza accurato in termini di come il programma ha speso il suo tempo, a patto che abbiamo preso abbastanza campioni.

Eliot: Una libreria di log

L’ultimo strumento che copriremo in dettaglio è Eliot, una libreria di log che ho scritto e che risolve gli altri due problemi che abbiamo visto con cProfile:

• Il log può essere usato in produzione.
• Il log può registrare gli argomenti delle funzioni.

Come vedrete, Eliot fornisce alcune capacità uniche che lo rendono migliore nel registrare le prestazioni rispetto alle normali librerie di log.Detto questo, con un po’ di lavoro in più potete ottenere gli stessi benefici anche da altre librerie di log.

Aggiungere il logging al codice esistente

Considerate il seguente schizzo di un programma:

Possiamo prendere questo codice e aggiungervi del logging:

In particolare, facciamo due cose:

1. Dire a Eliot dove emettere i messaggi di log (in questo caso, un file chiamato “out.log”).
2. Decoriamo le funzioni con un decoratore @log_call.Questo registrerà il fatto che la funzione è stata chiamata, i suoi argomenti e il valore di ritorno (o l’eccezione sollevata).

Eliot ha altre API più dettagliate, ma @log_call è sufficiente per dimostrare i benefici del log.

L’output di Eliot

Una volta eseguito il programma, possiamo guardare i log usando uno strumento chiamato eliot-tree:

Nota che, un po’ come Pyinstrument, stiamo guardando un albero di azioni.Ho semplificato un po’ l’output – originariamente per poterlo inserire in una diapositiva che ho usato nella versione talk di questo articolo – ma anche in un articolo in prosa ci permette di concentrarci sull’aspetto della performance.

In Eliot, ogni azione ha un inizio e una fine, e può iniziare altre azioni – quindi l’albero risultante.Poiché sappiamo quando ogni azione registrata inizia e finisce, sappiamo anche quanto tempo ha impiegato.

In questo caso, ogni azione corrisponde a una chiamata di funzione.E ci sono alcune differenze dall’output di Pyinstrument:

1. Invece di combinare più chiamate di funzione, si vede ogni singola chiamata separatamente.
2. Si possono vedere gli argomenti e il risultato di ritorno di ogni chiamata.
3. Si può vedere il tempo wallclock trascorso di ogni azione.

Per esempio, si può vedere che multiplysum() ha richiesto 10 secondi, ma la maggior parte del tempo è stata spesa in multiply(), con gli ingressi 3 e 4.Quindi sai subito che per l’ottimizzazione delle prestazioni vuoi concentrarti su multiply(), e hai alcuni input di partenza (3 e 4) con cui giocare.

I limiti del logging

Il logging non è sufficiente da solo come fonte di informazioni sulle prestazioni.

In primo luogo, ottieni informazioni solo dal codice in cui hai aggiunto esplicitamente le chiamate di logging.Un profiler può essere eseguito su qualsiasi pezzo arbitrario di codice senza alcuna preparazione preventiva, ma con il logging dovete fare del lavoro in anticipo.

Se non avete aggiunto codice di logging, non otterrete alcuna informazione.Eliot rende questo un po’ meglio, poiché la struttura ad albero delle azioni vi dà un senso di dove è stato speso il tempo, ma non è ancora sufficiente se il logging è troppo scarso.

In secondo luogo, non puoi aggiungere il logging ovunque perché questo rallenterà il tuo programma.Il logging non è economico – è un overhead maggiore di cProfile.Quindi devi aggiungerlo con giudizio, nei punti chiave dove massimizzerà le informazioni che dà senza impattare sulle prestazioni.

Scegliere gli strumenti giusti

Quindi quando dovresti usare ogni strumento?

Aggiungi sempre il logging

Ogni programma non banale probabilmente ha bisogno di un po’ di logging, anche solo per catturare bug ed errori.E se stai già aggiungendo il logging, puoi prenderti la briga di registrare anche le informazioni che ti servono per fare il debug delle prestazioni.

Eliot lo rende più facile, dato che il logging delle azioni fornisce intrinsecamente il tempo trascorso, ma è possibile, con un po’ di lavoro extra, fare questo con qualsiasi libreria di logging.

Il logging potrebbe aiutarvi a individuare il luogo specifico in cui il vostro programma è lento, e come minimo alcuni input che causano lentezza, ma spesso non è sufficiente.Quindi il passo successivo è usare un profiler, e in particolare un profiler di campionamento come Pyinstrument:

• Ha un basso overhead, e soprattutto non distorce i risultati.
• Misura il tempo wallclock, quindi non presume che la CPU sia il collo di bottiglia.
• Fa uscire solo le funzioni più lente, omettendo le funzioni veloci irrilevanti.

Utilizza cProfile se hai bisogno di una metrica di costo personalizzata

Se hai bisogno di scrivere un profilatore personalizzato, cProfile ti permette di inserire diverse funzioni di costo, rendendolo uno strumento facile per misurare metriche più insolite.

Puoi misurare:

• Non-CPU, tutto il tempo passato in attesa di eventi non-CPU.
• Il numero di cambi di contesto volontari, cioè il numero di chiamate di sistema che richiedono molto tempo.
• Le allocazioni di memoria.
• Più in generale, qualsiasi contatore che sale.

TL;DR

Come buon punto di partenza sugli strumenti di ottimizzazione delle prestazioni, vi suggerisco di:

1. Logare i principali input e output, e il tempo trascorso delle azioni chiave, usando Eliot o qualche altra libreria di log.
2. Utilizzare Pyinstrument – o un altro profilatore di campionamento – come profilatore predefinito.
3. Utilizzare cProfile se avete bisogno di un profilatore personalizzato.