Qual è la relazione tra il tempo della CPU misurato da Python Profiler e, real, user e sys time?

Question

Uso del pitone incorporato profilatore con uno script runninng in un processore (e senza multithreading)

time python -m cProfile myscript.py 

il tempo di CPU riportato dal Profiler 345.710 CPU secondi

24184348 function calls (24183732 primitive calls) in 345.710 CPU seconds 

e vera, utente e sys tempo sono:

real 5m45.926s 
user 1m59.340s 
sys  0m39.452s 

Come si può vedere il tempo della CPU è quasi il tempo reale (345.710 = 5m45.710s).

Quindi, dato quel risultato, è possibile ipotizzare che il tempo di CPU segnalato dal profiler includa le fasce orarie utilizzate da altri processi e il tempo che il processo spende bloccato? vale a dire che il tempo di profiler CPU non è il tempo di processo (utente + sys), ma il tempo di orologio da parete, come è spiegato in What do 'real', 'user' and 'sys' mean in the output of time(1)?

Grazie mille in anticipo

Answer 1

This answers splendidamente dettagli sul significato di vera e propria, i tempi dell'utente e del sistema. Per quotare:

• 'Reale' è l'ora dell'orologio da parete - tempo dall'inizio alla fine della chiamata. Questo è tutto il tempo trascorso, comprese le fasce orarie utilizzate da altri processi e tempo di attesa del processo (ad esempio se è in attesa di I/O da completare).

• 'Utente' è la quantità di tempo impiegato dalla CPU nel codice in modalità utente (all'esterno del kernel ) all'interno del processo. Questo è solo il tempo effettivo della CPU utilizzato in in esecuzione del processo. Altri processi e tempi trascorsi dal processo bloccati non vengono conteggiati per questa cifra.

• 'Sys' è la quantità di tempo CPU trascorso nel kernel all'interno del processo. Ciò significa eseguire il tempo di CPU trascorso nelle chiamate di sistema all'interno del kernel , al contrario del codice di libreria, che è ancora in esecuzione nello spazio utente . Come "utente", questa è solo la CPU utilizzata dal processo.

Dalla spiegazione precedente appare come il tempo di utente + Sys dovrebbe essere uguale ai secondi della CPU. Invece, è più vicino al tempo "reale". Strano!

C'è una spiegazione equa per questo. L'ora dell'utente è non include i secondi CPU impiegati per le operazioni di I/O all'interno del processo. Misura solo il tempo impiegato dalla CPU per il codice in modalità utente all'interno della memoria . La regola generale è:

tempo reale = utente + sys + tempo di I/O + interprete tempo di avvio + bytecode tempo di compilazione

per convalidare questa ho fatto una urllib2.urlopen(urllib2.Request(url)) chiamata a fare I intensiva/O .Ecco i risultati:

  100792 function calls (98867 primitive calls) in 2.076 CPU seconds 

    Ordered by: internal time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
     512 0.719 0.001 0.719 0.001 {method 'recv' of '_socket.socket' objects} 
     1 0.464 0.464 0.473 0.473 {_socket.getaddrinfo} 
     1 0.352 0.352 0.352 0.352 <string>:1(connect) 
     1 0.248 0.248 0.348 0.348 common_functions.py:1(<module>) 
     1 0.022 0.022 0.075 0.075 __init__.py:2(<module>) 
     1 0.017 0.017 0.030 0.030 urllib.py:1442(getproxies_macosx_sysconf) 
    330/67 0.012 0.000 0.031 0.000 sre_parse.py:385(_parse) 


real 0m2.255s 
user 0m0.352s 
sys 0m0.093s 

Qui, 2.076- (0,352 + 0,093), cioè, 1.631 secondi CPU sono stati consumati nelle operazioni di I/O (principalmente _socket.socket e _socket.getaddrinfo). Il resto del tempo, 2.255-2.076, è stato speso all'inizio a freddo del codice.

Spero che sia stato utile.

Aggiornamento: in più sistemi core, dove più CPU lavorano in parallelo, il caso è leggermente diverso. Totale secondi CPU riportati da cProfile è la somma totale del tempo trascorso da tutte le CPU individualmente. Ad esempio: in un sistema a 2 core, se una CPU funziona per 10 secondi. In parallelo, un'altra CPU funziona per 15 secondi. I secondi totali della CPU riportati saranno 25 secondi. Anche se il tempo reale trascorso può essere solo 15 secondi. Quindi il tempo della CPU può essere maggiore del tempo reale nei sistemi multi core. Mentre le CPU funzionano in parallelo

Answer 2

Sono rimasto perplesso dallo stesso problema.

La risposta è che cProfile utilizza il tempo del wallclock. E il suo output è storicamente sbagliato ma è stato risolto (la 'CPU' in 'CPU seconds' è stata rimossa). Non so esattamente quando, ma Python 2.6.6 in Debian 6.0 ha il bug mentre Python 2.7.3 in Debian 7.0 va bene.

Questo è sconcertante perché la maggior parte dei profiler tiene conto del tempo speso per la CPU e non per il tempo di wallclock. Ma questo è un profiler "economico".

Il documento http://docs.python.org/2/library/profile.html#limitations spiega - non chiaramente - che il tempismo è basato su un ticking wallclock e non su getrusage() o su tecniche ptrace.

Se si controlla il codice (http://hg.python.org/cpython/file/44f455e6163d/Modules/_lsprof.c) è possibile verificare che sia basato su QueryPerformanceFrequency/gettimeofday.

Jerrymouse ha ragione sul fatto che il 'tempo' e le tempistiche Cprofile non possono coincidere, perché Cprofile inizia solo una volta in esecuzione il codice viene compilato. Ma oltre a ciò la sua equazione 'in tempo reale' è falsa.

La differenza tra wallclock e user + sys può trovarsi in molti fattori diversi, come l'I/O per conto del processo O per conto di qualsiasi altro processo incluso il kernel stesso (swapping, journaling, ecc.) O CPU tempo speso per altri processi, o in attesa di qualcosa per conto del tuo processo che non può essere contabilizzato perché è una risorsa remota (rete, o indiretta tramite NFS o iSCSI), ecc.

Answer 3

Il profiler Python misura il tempo di parete per impostazione predefinita, ma può essere eseguito per misurare il tempo della CPU utilizzando una funzione timer personalizzata. I seguenti lavori sotto Linux, ma non Windows (dal momento time.clock misure a muro su Windows):

import cProfile 
import time 


def idleWait(): 
    time.sleep(10) 

def busyWait(): 
    t = time.time() + 10 
    while time.time() < t: pass 

def target(): 
    idleWait() 
    busyWait() 


print "Wall time:" 
p = cProfile.Profile() 
p.runcall(target) 
p.print_stats() 

print "CPU time:" 
p = cProfile.Profile(time.clock) 
p.runcall(target) 
p.print_stats() 

La prima esecuzione profilo mostrerà 20 secondi trascorsi, con circa la metà dei quali trascorso in time.sleep. Il secondo mostra 10 secondi trascorsi, nessuno dei quali è stato speso in time.sleep.