cProfile with imports

Question

I'm currently in the process of learn how to use cProfile and I have a few doubts.

I'm currently trying to profile the following script:

import time

def fast():
    print("Fast!")

def slow():
    time.sleep(3)
    print("Slow!")

def medium():
    time.sleep(0.5)
    print("Medium!")

fast()
slow()
medium()

I execute the command python -m cProfile test_cprofile.py and I have the following result:

Fast!
Slow!
Medium!
     7 function calls in 3.504 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    3.504    3.504 test_cprofile.py:1(<module>)
    1    0.000    0.000    0.501    0.501 test_cprofile.py:10(medium)
    1    0.000    0.000    0.000    0.000 test_cprofile.py:3(fast)
    1    0.000    0.000    3.003    3.003 test_cprofile.py:6(slow)
    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    2    3.504    1.752    3.504    1.752 {time.sleep}

However, when I edit the script with a pylab import for example (import pylab) on the top, the output of cProfile is very large. I tried to limit the number of lines using python -m cProfile test_cprofile.py | head -n 10 however I receive the following error:

Traceback (most recent call last):
File "/home/user/anaconda/lib/python2.7/runpy.py", line 162, in _run_module_as_main
"__main__", fname, loader, pkg_name)
File "/home/user/anaconda/lib/python2.7/runpy.py", line 72, in _run_code
exec code in run_globals
File "/home/user/anaconda/lib/python2.7/cProfile.py", line 199, in <module>
main()
File "/home/user/anaconda/lib/python2.7/cProfile.py", line 192, in main
runctx(code, globs, None, options.outfile, options.sort)
File "/home/user/anaconda/lib/python2.7/cProfile.py", line 56, in runctx
result = prof.print_stats(sort)
File "/home/user/anaconda/lib/python2.7/cProfile.py", line 81, in print_stats
pstats.Stats(self).strip_dirs().sort_stats(sort).print_stats()
File "/home/user/anaconda/lib/python2.7/pstats.py", line 360, in print_stats
self.print_line(func)
File "/home/user/anaconda/lib/python2.7/pstats.py", line 438, in print_line
print >> self.stream, c.rjust(9),
IOError: [Errno 32] Broken pipe

Can someone help what is the correct procedure to situations similar with this one, where we have an import pylab or another module that generates such high output information on cProfile?

Answer 1

I don't know of any way to do the selective profiling like you want by running the cProfile module directly from the command line like you're doing.

However, you can do it by modifying the your code to explicitly import the module, but you'll have to do everything yourself. Here's how that might be done to your example code:

^{(Note: The following code is compatible with both Python 2 and 3.)}

from cProfile import Profile
from pstats import Stats
prof = Profile()

prof.disable()  # i.e. don't time imports
import time
prof.enable()  # profiling back on

def fast():
    print("Fast!")

def slow():
    time.sleep(3)
    print("Slow!")

def medium():
    time.sleep(0.5)
    print("Medium!")

fast()
slow()
medium()

prof.disable()  # don't profile the generation of stats
prof.dump_stats('mystats.stats')

with open('mystats_output.txt', 'wt') as output:
    stats = Stats('mystats.stats', stream=output)
    stats.sort_stats('cumulative', 'time')
    stats.print_stats()

mystats_output.txt file's contents afterwards:

Sun Aug 02 16:55:38 2015    mystats.stats

         6 function calls in 3.522 seconds

   Ordered by: cumulative time, internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    3.522    1.761    3.522    1.761 {time.sleep}
        1    0.000    0.000    3.007    3.007 cprofile-with-imports.py:15(slow)
        1    0.000    0.000    0.515    0.515 cprofile-with-imports.py:19(medium)
        1    0.000    0.000    0.000    0.000 cprofile-with-imports.py:12(fast)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Update:

You can make enabling the profiling a little easier by deriving your own Profile class with a context manager method to automate things. Instead of adding a method with a name like enable_profiling() to do this, I've implemented it so that you can just call the class instance in a with statement. Profiling will automatically be turned off whenever the context controlled by the with statement is exited.

Here's the class:

from contextlib import contextmanager
from cProfile import Profile
from pstats import Stats

class Profiler(Profile):
    """ Custom Profile class with a __call__() context manager method to
        enable profiling.
    """
    def __init__(self, *args, **kwargs):
        super(Profile, self).__init__(*args, **kwargs)
        self.disable()  # Profiling initially off.

    @contextmanager
    def __call__(self):
        self.enable()
        yield  # Execute code to be profiled.
        self.disable()

Using it instead of a stock Profile object would look something like this:

profiler = Profiler()  # Create class instance.

import time  # Import won't be profiled since profiling is initially off.

with profiler():  # Call instance to enable profiling.
    def fast():
        print("Fast!")

    def slow():
        time.sleep(3)
        print("Slow!")

    def medium():
        time.sleep(0.5)
        print("Medium!")

    fast()
    slow()
    medium()

profiler.dump_stats('mystats.stats')  # Stats output generation won't be profiled.

with open('mystats_output.txt', 'wt') as output:
    stats = Stats('mystats.stats', stream=output)
    stats.strip_dirs().sort_stats('cumulative', 'time')
    stats.print_stats()

# etc...

Since it's a Profile subclass, all the base class' methods, such as dump_stats() are all still available for use as shown.

You could, of course, take it further and add e.g. a method to generate the stats and format them in some customized way.

Answer 2

If you change your script slightly, then it'll be much easier to profile the script without also profiling your imports.

test_cprofiler.py

import time
import pylab

def fast():
    print("Fast!")

def slow():
    time.sleep(3)
    print("Slow!")

def medium():
    time.sleep(0.5)
    print("Medium!")

def main():
    fast()
    slow()
    medium()

if __name__ == "__main__":
    main()

profiler.py

import cProfile

import test_cprofiler

cProfile.run("test_cprofiler.main()")

Run as:

python profiler.py

Which produces the following output:

Fast!
Slow!
Medium!
         8 function calls in 3.498 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.498    3.498 <string>:1(<module>)
        1    0.000    0.000    2.998    2.998 run.py:11(slow)
        1    0.000    0.000    3.498    3.498 run.py:15(main)
        1    0.000    0.000    0.000    0.000 run.py:4(fast)
        1    0.000    0.000    0.500    0.500 run.py:7(medium)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    3.498    1.749    3.498    1.749 {time.sleep}