Profiling in Python

If you are interested in profiling in Python we are working on new profiler https://github.com/vmprof/vmprof-python. which by design is created to work with PyPy as well.

I use gprof2dot together with cProfile:

https://taoofmac.com/space/blog/2014/07/07/2030

Here's a handy command line for it:

https://github.com/rcarmo/sushy/blob/master/Makefile#L86

...and a large diagram of a profiling session:

https://github.com/rcarmo/sushy/blob/master/pages/blog/2015/...

Maybe I missed something, but using cProfile to read the produced stats is a bit of a pain in the neck. I was debugging a django application, where every request involves a large call stack either through the django web server or (in my unfortunate case) through the templating library, so a lot of cruft was in the profile. I had to dig through the underlying dicts that made up the stats output.

Never heard of Python Call Graph, will check it out.

Having some background knowledge of how Python implements some of its types can also be useful when debugging performance issues. For instance, knowing that the Python list type is implemented using a variable-length array of object references (rather than a linked-list) will help one figure out why inserting in the front or middle of a Python list is slow.

https://docs.python.org/2/faq/design.html#how-are-lists-impl...

I'm fairly spoiled by Perl's Devel::NYTProf. Example profiler output: http://moritz.faui2k3.org/tmp/otrs-tt/

It makes it pretty obvious where time is spent, and every piece in the flame graph (and in the list of routines below) is a link to the source code, with each line annotated by number of calls and time spent.

Regarding caching, fastcache is a faster drop in replacement for functools lru cache: https://pypi.python.org/pypi/fastcache/0.4.0

I'll add another shameless plug here. I wrote nosetests plugion for profiling your test suites called nose-perfdump

https://github.com/etscrivner/nose-perfdump

I'm a fan of line_profiler: https://github.com/rkern/line_profiler

        % cat > l.py
        @profile
        def slow_func():
            for i in xrange(1048576):
                continue
            
            return -1
        
        @profile
        def fast_func():
            for i in xrange(10):
                continue
            
            return -1
        @profile
        def the_func():
            for i in xrange(10):
                slow_func()
                fast_func()
                
        if __name__ == "__main__":
            the_func()
            
        % kernprof -l l.py
        % python -m line_profiler l.py.lprof
          Timer unit: 1e-06 s
            
            Total time: 5.21814 s
            File: l.py
            Function: slow_func at line 1
            
            Line #      Hits         Time  Per Hit   % Time  Line Contents
            ==============================================================
                    1                                           @profile
                    2                                           def slow_func():
                    3  10485770      2644263      0.3     50.7      for i in xrange(1048576):
                    4  10485760      2573875      0.2     49.3          continue
                    5                                               
                    6        10            5      0.5      0.0      return -1
            
            Total time: 8.9e-05 s
            File: l.py
            Function: fast_func at line 8
            
            Line #      Hits         Time  Per Hit   % Time  Line Contents
            ==============================================================
                    8                                           @profile
                    9                                           def fast_func():
                    10       110           61      0.6     68.5      for i in xrange(10):
                    11       100           26      0.3     29.2          continue
                    12                                               
                    13        10            2      0.2      2.2      return -1
            
            Total time: 10.5501 s
            File: l.py
            Function: the_func at line 14
            
            Line #      Hits         Time  Per Hit   % Time  Line Contents
            ==============================================================
                    14                                           @profile
                    15                                           def the_func():
                    16        11            3      0.3      0.0      for i in xrange(10):
                    17        10     10549853 1054985.3    100.0          slow_func()
                    18        10          203     20.3      0.0          fast_func()

runsnakerun is another good visualizer for cProfile: http://www.vrplumber.com/programming/runsnakerun/