Profiling and visualization tools in Python

Which part of the my python code is taking time ? Have you had this question ever?

Well, I have that question pop up quite often, especially when dealing with legacy code. This is my effort in helping people, who are in the same boat

Consider the following simple piece of code in a file called test.py

def print_method():
    print("hello world")
def test_print_method():
    for i in xrange(2):
        print_method()
for i in range(3):
    test_print_method()

When you execute the code using pythonexecutable, following output of hello worldis printed 6 times

$ python test.py
hello world
hello world
hello world
hello world
hello world
hello world

Let’s look in to different tools which we could use to determine

• Code path
• Number of calls and
• Which method took the most time !

Disclaimer:

This blog has been created after executing the commands on a Linux distro. If on a different platform, I assume one knows how to get to the required (or similar) software packages

We basically rely on profilemodule, more specificallycProfilemodule to generate the data needed for different visualization tools: https://docs.python.org/2/library/profile.html#module-profile

Easiest way to run cProfileon a python code is to run it as a module with python executable by passing the actual script as an argument to cProfile

Example

python -m cProfile test.py

Along with the expected output of hello world,we see additional information about the time it took to execute each method.

$ python -m cProfile test.py
hello world
hello world
hello world
hello world
hello world
hello world
         12 function calls in 0.000 seconds
Ordered by: standard name
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 test.py:1(<module>)
        6    0.000    0.000    0.000    0.000 test.py:1(print_method)
        3    0.000    0.000    0.000    0.000 test.py:5(test_print_method)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {range}

Output might not be super digestible instantly at the first glance. Lets dive into different visualization tools available which can make the timing information more perceivable

gprof2dot

My favorite one among all the available tools is gprof2dot(https://github.com/jrfonseca/gprof2dot)

1. Install gprof2dot

pip install gprof2dot --user

2. Execute the test.pyscript this time with the timing information being directed to an external output file, rather than standard console output. Observe the -oflag with the output filename being test.pstats

python -m cProfile -o test.pstats test.py

3. Assuming you have dot and eoginstalled, run the following command in the terminal where the profiling output file test.pstatsis located

gprof2dot -f pstats test.pstats | dot -Tpng -o output.png && eog output.png

Bingo, you get a window which shows something like the following

output.png generated by gprof2dot

Above graph shows you that 91.67% was spent in test_print_methodand the same method was called 3 times ( 3x) , which in turn calls print_method(overall 6 times).

Other method calls like range is a tiny amount of total execution time, but it is also visible in the graph

This was a simple python code. This method works equally well with complex code. Pasting asample image from gprof2dot’s github repo

sample visualization by gprof2dot

SnakeViz

Snakeviz is a browser based visualization tool. It needs the output in a .profileformat, rather than .pstatswhen the profiling output is generated using cProfilemodule

1. Install snakeviz

pip install snakeviz --user

2. Execute the test.pyscript this time with the timing information being redirected using -oflag to output file namedtest.profile

python -m cProfile -o test.profile test.py

3. Run the following command in the terminal where the profiling output file test.profileis located

snakeviz test.profile

There will be some information printed in the console when the command is run and a new window which pops in a browser session

$ snakeviz test.profile 
snakeviz web server started on 127.0.0.1:8080; enter Ctrl-C to exit
http://127.0.0.1:8080/snakeviz/%2Ftmp%2Ftest.profile
START /usr/bin/google-chrome-stable "http://127.0.0.1:8080/snakeviz/%2Ftmp%2Ftest.profile"
Opening in existing browser session.
WARNING:tornado.access:404 GET /images/sort_both.png (127.0.0.1) 1.04ms
WARNING:tornado.access:404 GET /images/sort_desc.png (127.0.0.1) 0.49ms

snakeviz with Icicle visualization

snakeviz with sunburst visualization

snakeviz presents the profiling data in a different view than gprof2dot

PyCallGraph

This seems to be an abandoned project, but hey ! still works.

1. Install pycallgraph

pip install pycallgraph --user

2. Execute the script using pycallgraph executable, rather than going via python executable.

Disclaimer:

The following examples specify graphviz as the outputter, so it’s required to be installed

pycallgraph graphviz -- ./test.py

3. Above command generates a pycallgraph.pngimage. Open the image using any image viewer. Using eogas an example on my box

$ eog pycallgraph.png

pycallgraph.png

Shows the timing and number of calls information.

Conclusion

I still believe gprof2dotdoes a better job at giving % and eye tracks the flow in the graph much easier than other methods.