¿Cuál es la relación entre el tiempo de CPU medido por Python Profiler y el tiempo real, de usuario y sys?

Question

Utilizando el pitón integrado de perfiles con un guión runninng en un procesador (y sin multihilo)

time python -m cProfile myscript.py 

el tiempo de CPU ha informado el perfilador es 345.710 segundos de CPU

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

y la reales, usuario y sys tiempo son:

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

Como puede ver, el tiempo de CPU es casi el tiempo real (345.710 = 5m45.710s).

Por lo tanto, dado ese resultado, ¿es posible suponer que el tiempo de CPU informado por el generador de perfiles incluye los intervalos de tiempo utilizados por otros procesos y el tiempo que el proceso pasa bloqueado? es decir, que el tiempo de perfiles de la CPU no es el tiempo de proceso (usuario + sys) pero el tiempo de reloj de pared, como se explica en What do 'real', 'user' and 'sys' mean in the output of time(1)?

muchas gracias de antemano

Answer 1

This answers bellamente detalles sobre el significado de los bienes, tiempos de usuario y sys. Para citar:

• 'Real' es el reloj de pared, tiempo - tiempo de principio a fin de la llamada. Este es todo el tiempo transcurrido, incluidos los intervalos de tiempo utilizados por otros procesos y el tiempo que el proceso pasa bloqueado (por ejemplo, si está esperando a que se complete la E/S ).

• 'Usuario' es la cantidad de tiempo de CPU consumido en el código de modo de usuario (fuera del núcleo ) dentro del proceso. Este es solo el tiempo de CPU real utilizado en ejecutando el proceso. Otros procesos y el tiempo que el proceso pasa bloqueado no cuentan para esta figura.

• 'Sys' es la cantidad de tiempo de CPU consumido en el kernel dentro del proceso. Esto significa ejecutar el tiempo de CPU gastado en llamadas al sistema dentro del kernel , a diferencia del código de biblioteca, que aún se está ejecutando en el espacio de usuario . Como 'usuario', este es solo el tiempo de CPU utilizado por el proceso.

De la explicación anterior parece que el tiempo del Usuario + Sys debe ser igual a los segundos de la CPU. En cambio, está más cerca del tiempo "real". ¡Extraño!

hay una explicación justo para eso. 'User' time does not incluyen los segundos de CPU gastados en operaciones de E/S dentro del proceso. Simplemente mide el tiempo de CPU gastado en el código de modo de usuario dentro de la memoria . La regla de oro es:

tiempo real = usuario + sys + tiempo de E/S + intérprete de tiempo de arranque + código de bytes de tiempo de compilación

Para validar esta Hice un urllib2.urlopen(urllib2.Request(url)) llamada haciendo que intensiva de E/S .Estos son los resultados:

  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 

Aquí, 2.076- (0.352 + 0.093), es decir, 1.631 segundos de CPU se consumieron en las operaciones de E/S (principalmente _socket.socket y _socket.getaddrinfo). El resto del tiempo, 2.255-2.076, se gastó en el inicio en frío del código.

Espero que haya sido útil.

Actualización: en los sistemas con varios núcleos, donde varias CPU trabajan en paralelo, la carcasa es ligeramente diferente. El total de segundos de CPU informados por cProfile es la suma total del tiempo invertido por todas las CPU de forma individual. Por ejemplo: en un sistema de 2 núcleos, si una CPU funciona durante 10 segundos. En paralelo, otra CPU funciona durante 15 segundos. El tiempo total de CPU reportado será de 25 segundos. Aunque el tiempo real transcurrido puede ser de solo 15 segundos. Por lo tanto, el tiempo de CPU puede ser mayor que Real Time en sistemas multi core. Como las CPU funcionan en paralelo

Answer 2

Me he sentido confundido por el mismo problema.

La respuesta es que cProfile usa el tiempo de reloj de pared. Y su salida ha sido históricamente incorrecta, pero ahora está fija (la 'CPU' en 'CPU segundos' ha sido eliminada). No sé exactamente cuándo, pero Python 2.6.6 en Debian 6.0 tiene el error, mientras que Python 2.7.3 en Debian 7.0 está bien.

Esto es desconcertante porque la mayoría de los perfiles cuenta el tiempo pasado en la CPU y no el tiempo de reloj de pared. Pero este es un perfilador "barato".

El doc. http://docs.python.org/2/library/profile.html#limitations explica, no claramente, que el tiempo se basa en un tic-tac y no en getrusage() o técnicas de trazado.

Si marca el código (http://hg.python.org/cpython/file/44f455e6163d/Modules/_lsprof.c) puede verificar que se basa en QueryPerformanceFrequency/gettimeofday.

Jerrymouse tiene razón acerca del hecho de que las sincronizaciones 'hora' y cProfile no pueden coincidir porque cProfile solo comienza a ejecutarse una vez que se compila el código. Pero además de que su ecuación en "tiempo real" es falsa.

La diferencia entre el reloj de pared y el usuario + sistema puede deberse a muchos factores diferentes, como E/S en nombre de su proceso O en nombre de cualquier otro proceso, incluido el kernel (intercambio, diario, etc.) o CPU el tiempo empleado en otros procesos o la espera de algo en nombre de su proceso que no se puede contabilizar debido a que se trata de un recurso remoto (de red o indirecto a través de NFS o iSCSI), etc. Usted lo nombra.

Answer 3

El generador de perfiles de Python mide el tiempo de pared de forma predeterminada, pero se puede hacer para medir el tiempo de la CPU utilizando una función de temporizador personalizada. Las siguientes obras bajo Linux, pero no Windows (desde el tiempo de la pared time.clock medidas en 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() 

El primer perfil de ejecución mostrarán transcurrido 20 segundos, con aproximadamente la mitad de ellos en el pasado time.sleep. El segundo muestra 10 segundos transcurridos, sin que ninguno de ellos se haya gastado en time.sleep.