Perché le statistiche line-by-line per NYTProf non corrispondono ai totali?

Question

Ho uno script Perl che richiede circa 30 minuti per l'esecuzione, quindi ovviamente eseguo Devel :: NYTProf. Grande profiler. Per molti dei miei sottotitoli, sto ricevendo alcuni dati che non hanno senso per me.

Sto utilizzando con perl 5.10.0 su Linux utilizzando le impostazioni NYTProf predefinite.

Nell'output HTML, ciascuno dei sottotitoli ha una sezione riassuntiva che indica quanto tempo è trascorso nel sottotitolo e nei suoi figli e poi continua a fornirmi informazioni sulla linea.

Le statistiche di riga non si sommano al totale speso nella funzione. Cosa dà?

Ad esempio, ho una funzione che si dice utilizzi 233s (57 + 166). Il report numero per riga ha una riga che utilizza 20 secondi, un'altra che utilizza 4 e una che utilizza 2. Le altre righe sono < e la funzione non è così lunga.

Cosa posso fare per risolvere questo disallineamento?

Potrei passare a Perl 5.12 ma ci vorrebbe un po 'di lavoro per installare le dipendenze. Sono felice di eseguirlo in una modalità più lenta. C'è un modo per aumentare la frequenza di campionamento? Corri su una macchina più lenta?

Fare clic qui per un esempio: my NYTProf output. In questo caso, si dice che il sub utilizzi 225 secondi, ma l'aggiunta di tutti i numeri produce 56 secondi. Questa corsa era ottimizzazione spento:

setenv NYTPROF optimize=0:file=nytprof.optout 

Aggiornamento ho rieseguire con Perl 5.12 utilizzando il findcaller = 1 opzione segnala come suggerito con più o meno gli stessi risultati. (Ho eseguito un set di dati diverso)

Aggiornamento Tim B è giusto. Ho modificato alcuni dei miei sottotitoli chiave per fare il caching da soli invece di usare memoize ei risultati NYTProf sono di nuovo utili. Grazie, Tim.

Answer 1

Ho appena aggiunto questo alla documentazione NYTProf:

= head2 if e subroutine intervalli non corrispondono

NYTProf ha due profiler: una dichiarazione profiler che viene richiamato quando perl passa da una istruzione perl a un'altra e un profiler di subroutine che viene richiamato quando chiamate perl o restituisce da una subroutine.

I singoli timing istruzione per un subroutine di solito aggiungere fino a un po ' inferiore al tempo di esclusiva per il subroutine. Questo perché la gestione della chiamata di subroutine e i risparmi di ritorno sono inclusi nel tempo esclusivo per la subroutine. La differenza può essere solo un nuovo microsecondo ma che potrebbe diventare notevole per le subroutine che sono chiamate centinaia di migliaia di volte.

La dichiarazione profiler tiene traccia di come molto tempo è stato speso per le spese generali, come scrittura dati del profilo dichiarazione alla disco. Il profiler subroutine sottrae i costi generali che hanno accumulato tra l'immissione e lasciando la subroutine per fornire un profilo più preciso. Il profiler dell'istruzione è in genere molto veloce perché la maggior parte delle scritture viene bufferizzata per la compressione zip, quindi il profilatore per riga tende ad essere molto piccolo, spesso un singolo "tick". Il risultato è che l'overhead accumulato è piuttosto rumoroso. Questo diventa più significativo per le subroutine che vengono chiamate frequentemente e sono anche veloce. Questo può essere un altro, più piccolo, contributo alla discrepanza tra tempo di dichiarazione ed esclusivo volte.

Questo probabilmente spiega la differenza tra la somma della colonna temporale dell'istruzione (31,7 s) e il tempo esclusivo riportato per la subroutine (57,2 s). La differenza ammonta a circa 100 microsecondi per chiamata (che sembra un po 'alto, ma non in modo irragionevole).

Il profiler di istruzione tiene traccia di quanto tempo è stato speso per i costi generali, come scrivere i dati del profilo di istruzione su disco. Il profiler delle subroutine sottrae la differenza di costi generali tra l'ingresso e l'uscita dalla subroutine al fine di fornire un profilo più accurato.

Il profiler di istruzioni è in genere molto veloce perché la maggior parte delle scritture vengono bufferizzate per la compressione zip, quindi l'overhead del profiler per istruzione tende ad essere molto piccolo, spesso un singolo "tick". Il risultato è che l'overhead accumulato è piuttosto rumoroso. Ciò diventa più significativo per le subroutine chiamate frequentemente e anche veloci (in questo caso chiamate 250303 a 899μs/chiamata). Quindi sospetto che questo sia un altro, più piccolo, contributo alla discrepanza tra tempo di dichiarazione e tempi esclusivi.

Ancora più importante, ho anche aggiunto questa sezione:

= head2 Se Headline subroutine intervalli non corrispondono i Subs Chiamato

complesso volte subroutine sono riportati con un titolo come "spesi 10s (2 + 8) entro ... ". In questo esempio, 10 secondi sono stati spesi all'interno della subroutine (il "tempo inclusivo") e, di questo, 8 secondi sono stati spesi nelle subroutine chiamate da questo. Che lascia 2 secondi come il tempo trascorso in il codice di subroutine stesso (il "tempo esclusivo", a volte anche chiamato "self time").

Il rapporto mostra il codice sorgente di la subroutine. Le linee che effettuano chiamate ad altre subroutine sono annotate con con i dettagli del tempo trascorso nelle chiamate .

volte la somma dei tempi di chiamate effettuate dalle linee di codice nel subroutine è minore della tempo compreso esclusiva riportato titolo (10-2 = 8 secondi dell'esempio sopra) .

Quello che sta succedendo qui è che le chiamate verso altre subroutine sono stati fatti, ma NYTProf non è in grado di determinare la posizione chiamando correttamente in modo che le chiamate non compaiono nella relazione in posto giusto.

L'utilizzo di una versione precedente di perl è una causa (see below). Un altro sta chiamando le subroutine che escono tramite "goto & sub;" - più frequentemente riscontrato in sottotitoli AUTOLOAD e codice utilizzando il modulo Memoize .

In generale i tempi complessiva subroutine è preciso e dovrebbe essere di fiducia più che la somma della dichiarazione o nidificate temporizzazioni sub chiamata.

Il modulo Memoize è la causa principale della discrepanza nel report. Le chiamate a Memoize::__ANON__[...] eseguono un sub generato da Memoize che assomiglia a sub { unshift @_, $cref; goto &_memoizer; }. Quel goto &_memoizer è implementato da perl come una sorta di ritorno al chiamante seguito da una chiamata al sub specificato, e questo è il modo in cui NYTProf lo profila.

La confusione è causato dal fatto che, anche se add_bit_to_map in registrazione del chiamante della _memoizer così il tempo nella chiamata viene aggiunto add_bit_to_map, il file e linea numero della posizione della chiamata viene registrata come la posizione del goto.

Potrebbe essere possibile migliorarlo in una versione futura.

Grazie per avermi spinto a indagare su questo e migliorare la documentazione.

Tim Bunce.

p.s. Raccomando di fare domande su NYTProf su mailing list.

Answer 2

Provare a disabilitare l'ottimizzatore di perl. Da CPAN's Devel::NYTProf docs:

ottimizzare = 0

Disabilitare l'ottimizzatore perl.

Per impostazione predefinita, NYTProf lascia abilitato l'ottimizzatore di perl. Questo ti dà più tempo per il profilo preciso , ma può portare a conteggi di istruzioni dispari per singoli gruppi di linee. Questo è perché l'ottimizzatore di spioncino di Perl ha effettivamente riscritto le dichiarazioni ma non è possibile vedere come si presenta la versione riscritta .

Ad esempio:

1  if (...) { 
2   return; 
3  } may be rewritten as 

1 return if (...) 

in modo che il profilo non mostrerà conta una dichiarazione per la linea 2 nel codice sorgente perché il ritorno è stata fusa nella se dichiarazione sulla riga precedente.

Utilizzando l'ottimizzare = 0 opzione disabilita l'ottimizzatore modo si otterrà inferiore prestazioni complessive ma più conta dichiarazione assegnati in modo accurato.

Se trovate altri esempi dell'effetto di ottimizzatore sull'uscita NYTProf (altro che le prestazioni, ovviamente) fatecelo sapere.