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

Question

使用 python 内置分析器和在一个处理器中运行的脚本（并且没有多线程）

time python -m cProfile myscript.py

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

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

而real、user和sys时间分别是：

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

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

那么，鉴于该结果，是否可以假设分析器报告的 CPU 时间包括其他进程使用的时间片和进程阻塞的时间？即探查器 CPU 时间不是进程时间（用户+系统），而是挂钟时间，如在 What do 'real', 'user' and 'sys' mean in the output of time(1)?

提前非常感谢

Answer 1

This answers 精美地详细说明了真实、用户和系统时间的含义。引用：

• 'Real' 是挂钟时间 - 从通话开始到结束的时间。这 是所有经过的时间，包括其他进程使用的时间片，并且 进程阻塞的时间（例如，如果它正在等待 I/O 完成）。

• 'User' 是在用户模式代码中花费的 CPU 时间量（在 内核）在进程中。这只是实际使用的 CPU 时间 执行过程。其他流程和流程花费的时间 被阻止不计入此数字。

• 'Sys' 是进程内在内核中花费的 CPU 时间量。 这意味着执行在系统调用中花费的 CPU 时间 内核，与仍在运行的库代码相反 用户空间。与“用户”一样，这只是进程使用的 CPU 时间。

从上面的解释看来，用户+系统时间应该等于 CPU 秒数。相反，它更接近“真实”时间。奇怪的！

对此有一个合理的解释。 “用户”时间不包括进程内用于 I/O 操作的 CPU 秒数。它只是测量在 内存 中用户模式代码所花费的 CPU 时间。经验法则是：

实时 = 用户 + 系统 + 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

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

希望有用。

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

Answer 2

我也被同样的问题困扰过。

答案是 cProfile 使用挂钟时间。它的输出在历史上一直是错误的，但现在已修复（“CPU seconds”中的“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 或代表包括内核本身（交换、日志等）在内的任何其他进程的 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 中。