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?
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.