Python Profiler测量的CPU时间与实际,用户和系统时间之间的关系是什么？

Question

在一个处理器中使用带有脚本runninng的python内置分析器(并且没有多线程)

time python -m cProfile myscript.py

分析器报告的CPU时间为345.710 CPU秒

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

而真实的,用户和系统的时间是:

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

如您所见,CPU时间几乎是实时(345.710 = 5m45.710s).

那么,鉴于该结果,是否可以假设分析器报告的CPU时间包括其他进程使用的时间片以及进程花费的时间？即,探查器CPU时间不是处理时间(用户+系统),而是挂钟时间,如 "真实","用户"和"系统"在时间输出(1)中的含义所述？

非常感谢提前

Answer 1

这回答了关于真实,用户和系统时间含义的精美细节.报价:

• '真实'是挂钟时间 - 从通话开始到结束的时间.这是所有经过的时间,包括其他进程使用的时间片和进程花费的时间(例如,如果它等待I/O完成).

• "用户"是进程内用户模式代码(内核外)花费的CPU时间.这只是执行过程时使用的实际CPU时间.流程花费的其他流程和时间不计入此数字.

• 'Sys'是进程内核中花费的CPU时间.这意味着执行内核中系统调用所花费的CPU时间,而不是仍在用户空间中运行的库代码.与'user'一样,这只是进程使用的CPU时间.

从上面的解释看,用户+系统时间应该等于CPU秒.相反,它更接近'真实'时间.奇怪!

对此有一个公平的解释."用户"时间并没有包括在过程中花费在I/O操作CPU秒.它只测量在内存中用户模式代码上花费的CPU时间.经验法则是:

实时=用户+ sys + I/O时间+解释器启动时间+字节码编译时间

为了验证这一点,我urllib2.urlopen(urllib2.Request(url))打电话进行密集的I/O. 结果如下:

         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

这里,在I/O操作(主要_socket.socket和_socket.getaddrinfo)中消耗了2.076-(0.352 + 0.093),即1.631个CPU秒.其余时间,2.255-2.076,用于冷启动代码.

希望这很有用.

更新:在多个核心系统中,多个CPU并行工作,情况略有不同.cProfile报告的总CPU秒数是所有CPU单独花费的时间总和.例如:在2核系统中,如果一个CPU工作10秒.同时,另一个CPU工作15秒.报告的总CPU秒数为25秒.虽然实际流逝的时间可能只有15秒.因此,在多核系统中CPU时间可能超过实时.由于CPU正在并行工作

Answer 2

我一直对同样的问题感到困惑.

答案是cProfile使用挂钟时间.它的输出在历史上是错误的,但现在已经修复('CPU秒'中的'CPU'已被删除).我不确切知道什么时候,但Debian 6.0中的Python 2.6.6有错误,而Debian 7.0中的Python 2.7.3很好.

这是令人费解的,因为大多数分析器都会花费在CPU上花费的时间,而不是壁钟时间.但这是一个"廉价"的探测器.

文档http://docs.python.org/2/library/profile.html#limitations解释 - 不清楚 - 时间是基于滴答作响的挂钟,而不是getrusage()或ptrace技术.

如果您检查代码(http://hg.python.org/cpython/file/44f455e6163d/Modules/_lsprof.c),则可以验证它是否为QueryPerformanceFrequency/gettimeofday.

Jerrymouse对'时间'和cProfile时间不能重合的事实是对的,因为cProfile只在代码编译后才开始运行.但除此之外,它的"实​​时"方程式也是假的.

wallclock和user + sys之间的区别可能在于许多不同的因素,例如代表您的进程的I/O或代表任何其他进程(包括内核本身(交换,日记等))或在其他进程上花费的CPU时间.进程,或代表您的进程等待任何无法计算的进程,因为它是远程资源(网络,或通过NFS或iSCSI间接),等等.

Answer 3

Python探查器默认测量挂起时间,但可以使用自定义计时器功能测量CPU时间.以下在Linux下工作,但不适用于Windows(因为time.clock在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()

第一个配置文件运行将显示20秒,其中大约一半用于time.sleep.第二个显示已经过了10秒,没有一个花在time.sleep.