Profiling Python Code

Profiling is a technique to figure out how time is spent in a program. With these statistics, we can find the “hot spot” of a program and think about ways of improvement. Sometimes, a hot spot in an unexpected location may hint at 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 the timeit module
• How we can profile the entire program using the cProfile module
• How we can invoke a profiler inside an existing program
• What the profiler cannot do

Kick-start your project with my new book Python for Machine Learning, including step-by-step tutorials and the Python source code files for all examples.

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 the + operator. So, how do we know which is faster? Consider the following Python code:

This will produce a long string 012345.... in the variable longstr. An 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 are 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 this is 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 starting the loop. Hence the time to create those strings is not measured in the “per loop” timing. The above shows that the join() function is two orders of magnitude faster than the + operator. The more common 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 use 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 the 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 total raw timing for each run:

In the above, each run is to execute the statement 10,000 times; the result is as follows. You can see the result of roughly 98 usec per loop in the best run:

The Profile Module

Focusing 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 be due to two reasons: A part is running slow, or a part is running too many times, adding up and taking too much time. We call these “performance hogs” the hot spot. Let’s look at an example. Consider the following program that uses a 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 101 times and took 4.89 seconds. But these 4.89 seconds are mostly spent on the functions it called, which the total time spent on that function is merely 0.001 seconds. 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: It 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:

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 the above, it will run the program. But this will not print the statistics to the screen but save them into a file. Afterward, we can use the pstats module like the following to open up the statistics file and provide us a prompt to manipulate the data:

For example, we can use the 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 show us which function calls which function, how many times it is called, and how much time is 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 call each other and want to know how the time is 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 remove this from the profiler. In this case, we can invoke the profiler only for certain lines. An example is as follows, which is 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, Tensorflow is supposed to build the computation graph before your model is executed, and hence the logic will be changed. The profiler output will therefore not show your custom classes.

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

Below is a short code of the 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 the majority of the time, and nothing can be shown beyond that:

In the result below, the TFE_Py_Execute is marked as a “built-in” method, and it consumes 30.1 sec out of the total run time of 39.6 sec. Note that the tottime is the same as the cumtime, meaning from the profiler’s perspective, it seems all time is 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, and pstats have their documentation in Python’s documentation:

• timeit module: https://docs.python.org/3/library/timeit.html
• cProfile module and pstats module: https://docs.python.org/3/library/profile.html

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 call each other using the GraphViz tool:

• Python Call Graph: https://pycallgraph.readthedocs.io/en/master/

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

• Valgrind: https://valgrind.org/

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

Summary

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

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

Get a Handle on Python for Machine Learning!

Be More Confident to Code in Python

...from learning the practical Python tricks

Discover how in my new Ebook:
Python for Machine Learning

It provides self-study tutorials with hundreds of working code to equip you with skills including:
debugging, profiling, duck typing, decorators, deployment, and much more...

Showing You the Python Toolbox at a High Level for
Your Projects

See What's Inside