Serious overhead in Python cProfile?

Question

Hi expert Pythonists out there, I am starting to use cProfile so as to have a more detailed timing information on my program. However, it's quite disturbing to me that there's a significant overhead. Any idea why cProfile reported 7 seconds while time module only reported 2 seconds in the code below?

# 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

Because it's doing a lot more work? time just times the whole operation, while cProfile runs it under instrumentation so it can get a detailed breakdown. Obviously, profiling is not meant to be used in production, so a 2.5x overhead seems like a small price to pay.

Answer 2

The function f returns very quickly. When you use cProfile, the time being attributed to one call to f is not accurate because the time is so small that it is comparable to the error in measuring time. The clock used to measure differences in time may only be accurate to 0.001s. So the error in each measurement may be orders of magnitude greater that the time you are trying to measure. Do this 1e7 times and you've got bogus results. (See http://docs.python.org/library/profile.html#limitations for more discussion of this.)

Notice that if you change the code to use

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)

you get

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}

You are doing the same number of loops, but each call to f takes longer. This cuts down on the error per measurement. (The time attributed to each call to f contains an error which is now not as large the total time measured.)