Python cProfile中的严重开销？

Question

大家好，我开始使用cProfile，以便对我的程序有更详细的计时信息。然而，这对我来说是相当麻烦的，因为它有很大的开销。你知道为什么在下面的代码中cProfile报告7秒，而time模块只报告2秒吗？

# a simple function

def f(a, b):
 c = a+b

# a simple loop
def loop():
 for i in xrange(10000000):
  f(1,2)

# timing using time module
# 2 seconds on my computer
from time import time
x = time()
loop()
y = time()
print 'Time taken %.3f s.' % (y-x)

# timing using cProfile
# 7 seconds on my computer
import cProfile
cProfile.runctx('loop()', globals(), locals())

Answer 1

因为它做了更多的工作？time只是对整个操作进行计时，而cProfile在指令插入下运行它，这样它就可以获得详细的细分。显然，性能分析并不是为了在生产中使用，因此2.5倍的开销似乎是一个很小的代价。

Answer 2

函数f返回得非常快。当您使用cProfile时，一次调用f的时间是不准确的，因为时间太小，可以与测量时间的误差相媲美。用于测量时间差的时钟可能只能精确到0.001秒。因此，每次测量的误差可能比您尝试测量的时间大几个数量级。这样做1e7次，你会得到虚假的结果。(有关这方面的更多讨论，请参阅http://docs.python.org/library/profile.html#limitations。)

请注意，如果将代码更改为使用

def f(a, b):
 for i in xrange(int(1e4)):    
     c = a+b

# a simple loop
def loop():
 for i in xrange(int(1e3)):
  f(1,2)

你会得到

Time taken 0.732 s.
         1003 function calls in 0.725 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.725    0.725 <string>:1(<module>)
     1000    0.723    0.001    0.723    0.001 test.py:4(f)
        1    0.001    0.001    0.725    0.725 test.py:9(loop)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

您正在执行相同数量的循环，但每次调用f所需的时间更长。这减少了每次测量的误差。(归因于每次调用f的时间包含一个错误，该错误现在不像测量的总时间那么大。)