This article explains the basics of profiling Python code. The hardest part is installing all the great tools that make it trivial to find the bottleneck in your code.

Getting the required tools

This can be a pain in the neck on a Mac. The rule of thumb I adhere to is Use conda, pip and homebrew where possible.

Python and core packages (numpy, scipy, etc)

Installing Python modules can sometimes be challenging as these link to compiled C/Fortran code behind the scenes. I recommend using conda, which can install pre-compiled modules for your operating system. Download from http://conda.pydata.org/miniconda.html. conda can be installed to your home directory, which comes in handy on the cluster.

After that, you can easily set up a virtual environment and install many of the core packages:

conda create -n py3k anaconda python=3
conda install numpy

The first step above should prepend the newly set up Python interpreter to your path. If it doesn’t, prepend the path to the new interpreter by editing ~/.bashrc and ~/.bash_profile. Pip should also be installed— if it is not, type the following into a terminal conda install pip

Once conda and pip are up and running, you should always attempt to install new Python packages through them instead of from source. This will save a lot of headache in the long run as you won’t have to compile C/Fortran code.

Note

Some Python packages serve as a wrapper around other software, such as MySQLdb around mysql and bsddb around BerkeleyDB. The underlying software is best installed via homebrew. For instance, here is how to set up BerkeleyDB:

# install C/Fortran compilers, these will come in handy all the time
brew install gcc
# install berkeley to  /usr/local/Cellar/berkeley-db/<VERSION>
brew install berkeley-db
# install python wrapper, passing in the path to the berkeley-db installation
BERKELEYDB_DIR=/usr/local/Cellar/berkeley-db/5.3.15/ pip install bsddb3

Profiling result visualisation (Runsnakerun/ Snakeviz)

These tool are useful for finding which function calls take the most time. You cannot look inside of functions using these. The next section will explain how to profile a single function to find which lines take the most time.

I know of two great packages the can visualise the output of the Python profiler. snakeviz has some fancy features and written in pure Python. It is easier to set up and use, but somewhat slow. If you have profiled a large chunk of an application, snakeviz will give up. In practice, I found it’s only useful for small programs. runsnakerun is written in C, so it can display just about anything, but is somewhat trickier to install.

pip install snakeviz
pip install runsnakerun

For runsnakerun, you may also have to install SquareMap via brew/conda/pip.

To visualise the results of a profiling run with snakeviz type snakeviz out.prof where out.prof is the file output by the profiler (see below). If you get “Sorry, we were not able to load this profile! You can try profiling a smaller portion of your code.”, then you will have to use runsnakerun:

ipython qtconsole

In the window that opens, type from runsnakerun import runsnake runsnake.main()

then use the GUI to open out.prof.

The reason we are using ipython instead of launching runsnakerun from the terminal is that OSX restricts some applications’ access to the screen. The version of runsnakerun installed through pip is not an Apple “framework” and therefore cannot access the screen. There are multiple guides explaining how to get around this on the Internet, but none of them has worked for me.

IPython extensions

There are many great tutorials on how to set up and use the required IPython extensions, such as http://pynash.org/2013/03/06/timing-and-profiling.html .

These extensions are best used to profile single functions (see below). lprun and mprun are of particular interest. Also note prun prints as a table the same information that snakeviz/runsnakerun visualises. Personally I find the visualisation much more useful.

Profiling the entire application

To profile an entire application, run python -m cProfile -o out.prof mycode.py

This creates a file called out.prof, which can be visualised using snakeviz or runsnakerun. The visualisation might like this:

Image

The top left corner of that image can be read as - function _count_vocab took a total of 1.6s - 0.6s of which were spent in __contains__ (not visible in the image, you need to hover over the box in runsnakerun) - 0.2s of which were spent in __my_feature_extractor__, etc

This technique can be used to find out which functions take a long time.

Profiling functions

Having set up the required IPython extensions and identified bottleneck functions, we can profile and incrementally optimise these. Let’s illustrate this with a real example I was recently working on.

I have a function called calculate_log_odds, which does something rather simple but seems to take a lot of time. To profile it line by line, I ran the following command in IPython

# get some data to run the function with
import pickle
b = pickle.load(open('../statistics/stats-exp0-0-cv0-ev.MultinomialNB.pkl'))
X = b.tr_matrix
y = b.y_tr
# do the actual profiling
%lprun -f calculate_log_odds calculate_log_odds(X, y)

The output looks like this:

Total time: 2.36018 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     3                                           def calculate_log_odds(X, y):
     4                                               # todo this is quite slow
     5         1           14     14.0      0.0      log_odds = np.empty(X.shape[1])
     6         1           45     45.0      0.0      class0_indices = (y == sorted(set(y))[0])
     7      2466         1632      0.7      0.1      for idx in range(X.shape[1]):
     8      2465       864021    350.5     36.6          all_counts = X[:, idx].A.ravel()  # document counts of this feature
     9      2465      1378602    559.3     58.4          total_counts = sum(all_counts > 0)  # how many docs the feature occurs in
    10      2465        79524     32.3      3.4          count_in_class0 = sum(all_counts[class0_indices])  # how many of them are class 0
    11      2465         3871      1.6      0.2          p = float(count_in_class0) / total_counts;
    12      2465        29874     12.1      1.3          log_odds_this_feature = np.log(p) - np.log(1 - p)
    13      2465         2595      1.1      0.1          log_odds[idx] = log_odds_this_feature
    14         1            0      0.0      0.0      return log_odds

Most of the time is spent on line 9, where I am using the Python sum function to add up a numpy array. This can be made much faster by using the appropriate numpy function:

Function: calculate_log_odds2 at line 16
Total time: 1.54092 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    16                                           def calculate_log_odds2(X, y):
    17         1           16     16.0      0.0      log_odds = np.empty(X.shape[1])
    18         1           55     55.0      0.0      class0_indices = (y == sorted(set(y))[0])
    19         1          526    526.0      0.0      X = X.tocsc()
    20      2466         1746      0.7      0.1      for idx in range(X.shape[1]):
    21      2465      1417910    575.2     92.0          all_counts = X[:, idx].A.ravel()  # document counts of this feature
    22      2465        49792     20.2      3.2          total_counts = np.sum(all_counts > 0)  # how many docs the feature occurs in
    23      2465        32936     13.4      2.1          count_in_class0 = np.sum(all_counts[class0_indices])  # how many of them are class 0
    24      2465         4377      1.8      0.3          p = float(count_in_class0) / total_counts;
    25      2465        30788     12.5      2.0          log_odds_this_feature = np.log(p) - np.log(1 - p)
    26      2465         2769      1.1      0.2          log_odds[idx] = log_odds_this_feature
    27         1            1      1.0      0.0      return log_odds

Note the running time has gone down from 2.3s to 1.5s. Now the bottleneck of the function seems to be at line 21, where I slice a sparse matrix and unnecessarily convert to it a dense one. After a few more iterations of 1) find bottleneck line, and 2) correct line, I arrived at the following:

Total time: 0.058181 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    56                                           def calculate_log_odds5(X, y):
    57         1           13     13.0      0.0      log_odds = np.empty(X.shape[1])
    58         1           47     47.0      0.1      class0_indices = y == sorted(set(y))[0]
    59         1          619    619.0      1.1      X = X.A
    60      2466         1792      0.7      3.1      for idx in range(X.shape[1]):
    61      2465         8277      3.4     14.2          all_counts = X[:, idx]  # document counts of this feature
    62      2465         7354      3.0     12.6          total_counts = np.count_nonzero(all_counts)  # how many docs the feature occurs in
    63      2465         8044      3.3     13.8          count_in_class0 = np.count_nonzero(all_counts[class0_indices])  # how many of them are class 0
    64      2465         3521      1.4      6.1          p = float(count_in_class0) / total_counts
    65      2465        25890     10.5     44.5          log_odds_this_feature = np.log(p) - np.log(1 - p)
    66      2465         2623      1.1      4.5          log_odds[idx] = log_odds_this_feature
    67         1            1      1.0      0.0      return log_odds

The running time is now 0.05 seconds, or a speedup of ~50x. The bottleneck operation is now entirely done on numpy arrays, so there are no more low-hanging fruit.

Notes

  • Having unit tests for the functions that you are optimising is essential to making sure nothing gets broken.
  • Functions to be profiled line by line cannot be typed into the interactive shell and must be imported from a file on disk