Profiling Python Code

Profiling is a technique to figure out how time is spent in a program. With this statistics, we can find the “hot spot” of a program and think about ways of improvement. Sometimes, hot spot in unexpected location may hint a bug in the program as well.

In this tutorial, we will see how we can use the profiling facility in Python. Specifically, you will see

  • How we can compare small code fragments using timeit module
  • How we can profile the entire program using cProfile module
  • How we can invoke a profiler inside an existing program
  • What the profiler cannot do

Let’s get started.

Profiling Python Code. Photo by Prashant Saini. Some rights reserved.

Tutorial Overview

This tutorial is in four parts; they are:

  • Profiling small fragments
  • The profile module
  • Using profiler inside code
  • Caveats

Profiling small fragments

When you are asked about the different ways of doing the same thing in Python, one perspective is to check which one is more efficient. In Python’s standard library, we have the timeit module that allows us to do some simple profiling.

For example, to concatenate many short strings, we can use the join() function from strings or use the + operator. So how we know which is faster? Consider the following Python code:

This will produce a long string 012345.... in the variabe longstr. Alternative way to write this is:

To compare the two, we can do the following at the command line:

These two commands will produce the following output:

The above commands is to load the timeit module and pass on a single line of code for measurement. In the first case, we have two lines of statements and they are passed on to the timeit module as two separate arguments. In the same rationale, the first command can also be presented as three lines of statements (by breaking the for loop into two lines), but the indentation of each line needs to be quoted correctly:

The output of timeit is to find the best performance among multiple runs (default to be 5). Each run is to run the provided statements a few times (which is dynamically determined). The time is reported as the average to execute the statements once in the best run.

While it is true that the join function is faster than the + operator for string concatenation, the timing above is not a fair comparison. It is because we use str(x) to make short strings on the fly during the loop. The better way to do are the following:

which produces:

The -s option allows us to provide the “setup” code, which is executed before the profiling and not timed. In the above, we create the list of short strings before we start the loop. Hence the time to create those strings are not measured in the “per loop” timing. From the above, we see that the join() function is two orders of magnitude faster than the + operator. The more often use of the -s option is to import the libraries. For example, we can compare the square root function from Python’s math module, from numpy, and using the exponential operator ** as follows:

The above produces the following measurement, which we see that math.sqrt() is fastest while numpy.sqrt() is slowest in this particular example:

If you wonder why numpy is slowest, it is because numpy is optimized for arrays. You will see its exceptional speed in the following alternative:

where the result is:

If you prefer, you can also run timeit in Python code. For example, the following will be similar to the above, but give you the raw total timing for each run:

In the above, each run is to execute the statement 10000 times; the result is as follows, which you can see the result of roughly 98 usec per loop in the best run:

The profile module

Focus on a statement or two for performance is from a microscopic perspective. Chances are, we have a long program and want to see what is causing it to run slow. That happens before we can consider alternative statements or algorithms.

A program running slow can generally due to two reasons: A part is running slow, or a part is running too many times and that added up to take too much time. We call these “performance hogs” the hot spot. Let’s look at an example. Consider the following program that uses hill climbing algorithm to find hyperparameters for a perceptron model:

Assume we saved this program in the file hillclimb.py, we can run the profiler in the command line as follows:

and the output will be the following:

The normal output of the program will be printed first, and then the profiler’s statistics will be printed. From the first row, we see that the function objective() in our program has run for 101 times that took a total of 4.89 seconds. But this 4.89 seconds are mostly spent on the functions it called, which the total time that spent at that function is merely 0.001 second. The functions from dependent modules are also profiled. Hence you see a lot of numpy functions above too.

The above output is long and may not be useful to you as it can be difficult to tell which function is the hot spot. Indeed we can sort the above output. For example, to see which function is called the most number of times, we can sort by ncalls:

Its output is as follows, which says the get() function from a Python dict is the most used function (but it only consumed 0.03 seconds in total out of the 5.6 seconds to finish the program):

The other sort options are as follows:

Sort string Meaning
calls Call count
cumulative Cumulative time
cumtime Cumulative time
file File name
filename File name
module File name
ncalls Call count
pcalls Primitive call count
line Line number
name Function name
nfl Name/file/line
stdname Standard name
time Internal time
tottime Internal time

If the program takes some time to finish, it is not reasonable to run the program many times just to find the profiling result in a different sort order. Indeed, we can save the profiler’s statistics for further processing, as follows:

Similar to above, it will run the program. But this will not print the statistics to the screen but to save it into a file. Afterwards, we can use the pstats module like following to open up the statistics file and provide us a prompt to manipulate the data:

For example, we can use sort command to change the sort order and use stats to print what we saw above:

You will notice that the stats command above allows us to provide an extra argument. The argument can be a regular expression to search for the functions such that only those matched will be printed. Hence it is a way to provide a search string to filter.

This pstats browser allows us to see more than just the table above. The callers and callees commands shows us which function calls which function and how many times it is called, and how much time it spent. Hence we can consider that as a breakdown of the function level statistics. It is useful if you have a lot of functions that calls each other and wanted to know how the time spent in different scenarios. For example, this shows that the objective() function is called only by the hillclimbing() function but the hillclimbing() function calls several other functions:

Using profiler inside code

The above example assumes you have the complete program saved in a file and profile the entire program. Sometimes, we focus on only a part of the entire program. For example, if we load a large module, it takes time to bootstrap and we want to ignore this from profiling. In this case, we can invoke the profiler only for certain lines. An example is as follows, which modified from the program above:

it will output the following:

Caveats

Using profiler with Tensorflow models may not produce what you would expect, especially if you have written your own custom layer or custom function for the model. If you did it correctly, Tenorflow supposed to build the computation graph before your model is executed and hence the logic will be changed. The profiler output will therefore not showing your custom classes.

Similarly for some advanced modules that involve binary code. The profiler can see you called some functions and marked it as “built-in” methods but it cannot go any further into the compiled code.

Below is a short code of LeNet5 model for the MNIST classification problem. If you try to profile it and print the top 15 rows, you will see that a wrapper is occupying majority of the time and nothing can be shown beyond that:

In the result below, the TFE_Py_Execute is marked as “built-in” method and it consumes 30.1 sec out of the total run time of 39.6 sec. Note that the tottime is same as the cumtime meaning from profiler’s perspective, it seems all time are spent at this function and it doesn’t call any other functions. This illustrates the limitation of Python’s profiler.

Finally, Python’s profiler gives you only the statistics on time but not memory usage. You may need to look for another library or tools for this purpose.

Further Readings

The standard library modules timeit, cProfile, pstats have their documentation in Python’s documentation:

The standard library’s profiler is very powerful but not the only one. If you want something more visual, you can try out the Python Call Graph module. It can produce a picture of how functions calling each other using the GraphViz tool:

The limitation of not able to dig into the compiled code can be solved by not using the Python’s profiler but instead, use one for compiled programs. My favorite is Valgrind:

but to use it, you may need to recompile your Python interpreter to turn on debugging support.

Summary

In this tutorial, we learned what is a profiler and what it can do. Specifically,

  • We know how to compare small code with timeit module
  • We see Python’s cProfile module can provide us detailed statistics on how time is spent
  • We learned to use the pstats module against the output of cProfile to sort or filter

No comments yet.

Leave a Reply