cProfile taking a very long time

Question

I am starting to use cProfile to profile my python script. I have noticed something very weird.

When I use time to measure the running time of my script it takes 4.3 seconds.

When I use python -m cProfile script.py it takes 7.3 seconds.

When running the profiler within the code:

import profile
profile.run('main()')

it takes 63 seconds!!

I can understand why it might take a little more time when adding profiling, but why there is such a difference between using cProfile from outside or as part of the code? Is there a reason why it takes so much time when I use profile.run?

Answer 1

Oddly enough, what you're seeing is expected behavior. In the introduction to the profilers section of the Python docs, it states that profile adds "significant overhead to profiled programs" as compared to cProfile. The difference you're seeing is in the libraries you're using, not how you're calling them. Consider this script:

import profile
import cProfile

def nothing():
    return

def main():
    for i in xrange(1000):
        for j in xrange(1000):
            nothing()

    return

cProfile.run('main()')
profile.run('main()')

The output from cProfile shows main takes about 0.143 seconds to run, while the profile variant reports 1.645 seconds, which is ~11.5 times longer.

Now let's change the script again to this:

def nothing():
    return

def main():
    for i in xrange(1000):
        for j in xrange(1000):
            nothing()

    return

if __name__ == "__main__":
    main()

And call it with the profilers:

python -m profile test_script.py

Reports 1.662 seconds for main to run.

python -m cProfile test_script.py

Reports 0.143 seconds for main to run.

This shows that the way you launch the profilers has nothing to do with the discrepancy you've seen between cProfile and profile. The difference is caused by how the two profilers handle "events" such as function calls or returns. In both cases, there are software hooks all over your executing code that trigger callbacks to track these events and do things like update counters for the events and start or stop timers. However, the profile module handles all of these events natively in Python, which means your interpreter has to leave your code, execute the callback stuff, then return to continue with your code.

The same things have to happen with cProfile (execute the profiling callbacks), but it's much faster because the callbacks are written in C. A look at the two module files profile.py and cProfile.py demonstrates some differences:

1. profile.py is 610 lines while cProfile.py is only 199 - most of its functions are handled in C.
2. profile.py primarily utilizes Python libraries while cProfile.py imports "_lsprof", a C code file. Source can be viewed here.
3. The Profile class in profile.py doesn't inherit from any other class (line 111), while the Profile class in cProfile.py (line 66) inherits from _lsprof.Profiler, which is implemented in the C source file.

As the docs state, cProfile is generally the way to go, simply because it is mostly implemented in C, so everything is faster.

As an aside, you can improve the performance of profile by calibrating it. Details on how to do that are available in the docs There are more details about how/why all this stuff is the way it is in the Python docs sections on Deterministic Profiling and limitations.

TL;DR

cProfile is much faster because, as its name implies, most of it is implemented in C. This is in contrast to the profile module, which has to handle all of the profiling callbacks in native Python. Whether you invoke the profilers from the command line or manually inside your script has no effect on the time difference between the two modules.