Python cProfile的开销严重？

Question

嗨，各位Python高手，我最近开始使用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

这个函数 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 的时间包含的误差现在没有那么大，相对于总测量时间来说。）

Answer 2

因为它做的事情更多吗？time 只是简单地计算整个操作的时间，而 cProfile 是在监控的情况下运行它，这样就能得到更详细的时间分析。显然，性能分析工具不适合在生产环境中使用，所以多花2.5倍的时间似乎是个小代价。