Python Profiling - Part 1

I gave a talk on profiling python code at the 2012 Utah Open Source Conference. Here are the slides and the accompanying code.

There are three parts to this profiling talk:

  • Standard Lib Tools - cProfile, Pstats
  • Third Party Tools - line_profiler, mem_profiler
  • Commercial Tools - New Relic

This is Part 1 of that talk. It covers:

  • cProfile module - usage
  • Pstats module - usage
  • RunSnakeRun - GUI viewer

Why Profiling:

  • Identify the bottle-necks.
  • Optimize intelligently. 

In God we trust, everyone else bring data

cProfile:

cProfile is a profiling module that is included in the Python's standard library. It instruments the code and reports the time to run each function and the number of times each function is called. 

Basic Usage:

The sample code I'm profiling is finding the lowest common multiplier of two numbers. lcm.py

# lcm.py - ver1 
    def lcm(arg1, arg2):
        i = max(arg1, arg2)
        while i < (arg1 * arg2):
            if i % min(arg1,arg2) == 0:
                return i
            i += max(arg1,arg2)
        return(arg1 * arg2)

    lcm(21498497, 3890120)

Let's run the profiler.

$ python -m cProfile lcm.py 
     7780242 function calls in 4.474 seconds
    
    Ordered by: standard name
   
    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
         1    0.000    0.000    4.474    4.474 lcm.py:3()
         1    2.713    2.713    4.474    4.474 lcm.py:3(lcm)
   3890120    0.881    0.000    0.881    0.000 {max}
         1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
   3890119    0.880    0.000    0.880    0.000 {min}

Output Columns:

  • ncalls - number of calls to a function.
  • tottime - total time spent in the function without counting calls to sub-functions.
  • percall - tottime/ncalls
  • cumtime - cumulative time spent in a function and it's sub-functions.
  • percall - cumtime/ncalls

It's clear from the output that the built-in functions max() and min() are called a few thousand times which could be optimized by saving the results in a variable instead of calling it every time. 

    Pstats:

    Pstats is also included in the standard library that is used to analyze profiles that are saved using the cProfile module. 

    Usage:

    For scripts that are bigger it's not feasible to analyze the output of the cProfile module on the command-line. The solution is to save the profile to a file and use Pstats to analyze it like a database. Example:  Let's analyze shorten.py.

    $ python -m cProfile -o shorten.prof shorten.py   # saves the output to shorten.prof
    
    $ ls
    shorten.py shorten.prof

    Let's analyze the profiler output to list the top 5 frequently called functions.

    $ python 
    >>> import pstats
    >>> p  = pstats.Stats('script.prof')   # Load the profiler output
    >>> p.sort_stats('calls')              # Sort the results by the ncalls column
    >>> p.print_stats(5)                   # Print top 5 items
    
        95665 function calls (93215 primitive calls) in 2.371 seconds
        
       Ordered by: call count
       List reduced from 1919 to 5 due to restriction <5>
        
           ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        10819/10539    0.002    0.000    0.002    0.000 {len}
               9432    0.002    0.000    0.002    0.000 {method 'append' of 'list' objects}
               6061    0.003    0.000    0.003    0.000 {isinstance}
               3092    0.004    0.000    0.005    0.000 /lib/python2.7/sre_parse.py:182(__next)
               2617    0.001    0.000    0.001    0.000 {method 'endswith' of 'str' objects}

    This is quite tedious or not a lot of fun. Let's introduce a GUI so we can easily drill down. 

    RunSnakeRun:

    This cleverly named GUI written in wxPython makes life a lot easy. 

    Install it from PyPI using (requires wxPython)

    $ pip install SquareMap RunSnakeRun
    $ runsnake shorten.prof     #load the profile using GUI

    The output is displayed using squaremaps that clearly highlights the bigger pieces of the pie that are worth optimizing. 

    It also lets you sort by clicking the columns or drill down by double clicking on a piece of the SquareMap.

    Conclusion:

    That concludes Part 1 of the profiling series. All the tools except RunSnakeRun are available as part of the standard library. It is essential to introspect the code before we start shooting in the dark in the hopes of optimizing the code.

    We'll look at line_profilers and mem_profilers in Part 2. Stay tuned. 

    You are welcome to follow me on twitter (@amjithr).

    Memoization Decorator

    Recently I had the opportunity to give a short 10 min presentation on Memoization Decorator at our local UtahPython Users Group meeting. 

    Memoization: 

    • Everytime a function is called, save the results in a cache (map).
    • Next time the function is called with the exact same args, return the value from the cache instead of running the function.

    The code for memoization decorator for python is here: http://wiki.python.org/moin/PythonDecoratorLibrary#Memoize

    Example:

    The typical recursive implementation of fibonacci calculation is pretty inefficient O(2^n).   

    def fibonacci(num):
            print 'fibonacci(%d)'%num
            if num in (0,1):
                return num
            return fibonacci(num-1) + fibonacci(num-2)

    >>> math_funcs.fibonacci(4) # 9 function calls fibonacci(4) fibonacci(3) fibonacci(2) fibonacci(1) fibonacci(0) fibonacci(1) fibonacci(2) fibonacci(1) fibonacci(0) 3

    But the memoized version makes it ridiculously efficient O(n) with very little effort.

    import memoized
    @memoized
    def fibonacci(num):
        print 'fibonacci(%d)'%num
        if num in (0,1):
            return num
        return fibonacci(num-1) + fibonacci(num-2)
        
    >>> math_funcs.mfibonacci(4)  # 5 function calls
        fibonacci(4)
        fibonacci(3)
        fibonacci(2)
        fibonacci(1)
        fibonacci(0)
        3

    We just converted an algorithm from Exponential Complexity to Linear Complexity by simply adding the memoization decorator.

    Slides:

    Presentation:

    I generated the slides using LaTeX Beamer. But instead of writing raw LaTeX code I used reStructured Text (rst) and used rst2beamer script to generate the .tex file. 

    Source:

    The rst file and tex files are available in Github.

    https://github.com/amjith/User-Group-Presentations/tree/master/memoization_de...

     

    Productive Meter

    A few weeks ago I decided that I should suck it up and start learning how to develop for the web. After asking around, my faithful community brethren, I decided to learn Django from its docs

    ::Django documentation is awesome::

    Around this time I came across this post about Waking up at 5am to code. I tried it a few times and it worked wonders. I've been working on a small project that can keep track of my productivity on the computer. The concept is really simple, just log the window that is on top and find a way to display that data in a meaningful way. 

    Today's 5am session got me to a milestone on my project. I am finally able to visaulize the time I spend using a decent looking graph. Which is a huge milestone for someone who learned how to display html tables 3 weeks ago.

    Tools:

    A huge thanks to my irc friends and random geeks who wrote awesome blog posts and SO answers on every problem I encountered.

    I will be open-sourcing the app pretty soon. Stay tuned.

    Picking 'k' items from a list of 'n' - Recursion

    Let me preface this post by saying I suck at recursion. But it never stopped me from trying to master it. Here is my latest (successful) attempt at an algorithm that required recursion. 

    Background: 

    You can safely skip this section if you're not interested in the back story behind why I decided to code this up. 

    I was listening to KhanAcademy videos on probability. I was particularly intrigued by the combinatorics video. The formula to calculate the number of combinations of nCr was simple, but I wanted to print all the possible combinations of nCr. 

    Problem Statement:

    Given 'ABCD' what are the possible outcomes if you pick 3 letters from it to form a combination without repetition (i.e. 'ABC' is the same as 'BAC'). 

    At first I tried to solve this using an iterative method and gave up pretty quickly. It was clearly designed to be a recursive problem. After 4 hours of breaking my head I finally got a working algorithm using recursion. I was pretty adamant about not looking it up online but I seeked some help from IRC (Thanks jtolds). 

    Code: 

    def combo(w, l):
            lst = []
            if l < 1:
                return lst
            for i in range(len(w)):
                if l == 1:
                    lst.append(w[i])
                for c in combo(w[i+1:], l-1):
                    lst.append(w[i] + c)
            return lst

    Output:

    >>> combinations.combo('abcde',3)
        ['abc', 'abd', 'abe', 'acd', 'ace', 'ade', 'bcd', 'bce', 'bde', 'cde']

    Thoughts:

    • It helps to think about recursion with the assumption that an answer for step n-1 already exists.
    • If you are getting partial answers check the condition surrounding the return statement.
    • Recursion is still not clear (or easy). 

    I have confirmed that this works for bigger data sets and am quite happy with this small victory.

    Python Profiling

    I did a presentation at our local Python User Group meeting tonight. It was well received, but shorter than I had expected. I should've added a lot more code examples. 

    We talked about usage of cProfile, pstats, runsnakerun and timeit. 

    Here are the slides from the presentations: 

    The slides were done using latex-beamer, but I wrote the slides in reStructuredText and used rst2beamer to create the tex file which was then converted to pdf using pdflatex. 

    The source code for the slides are available on github.