Profiling Code

Indices and tables

• Index
• Module Index
• Search Page

Introduction

Python ships with two modules to assist in understanding the execution of your code.

The following code, profile_me.py, will be used in the examples that follow:

"""
profile_me.py : A small module to try code profiling with
"""


def get_even_coords(x_max, y_max):
    """
    Calculates the even coordinate pairs between [0:x_max] and [0:y_max]

    :param x_max: An integer giving the x coordinate to stop at.
    :param y_max: An integer giving the x coordinate to stop at.
    :return:  A list-of-tuples of the even coordinates
    """
    return [(x, y) for x in range(0, x_max) for y in range(0, y_max) if x % 2 == 0 and y % 2 == 0]


def sum_coords(coord_list):
    """
    Sums up all coordinate values and returns them.

    :param coords: A list-of-tuples of coordinates to sum
    :return: The sum.
    """
    all_coords = [coord for coord_pair in coord_list for coord in coord_pair]
    return sum(all_coords)


def main(x_max=10, y_max=10):
    """
    Calls the functions in the order we want to profile them in when the script
    is run at the command line.
    """
    coords = get_even_coords(x_max, y_max)
    return sum_coords(coords)

timeit

The timeit package provides functionality that allows you to benchmark the execution time of your code. One of the most popular functions to use from the package is:

repeat(stmt='pass', setup='pass', repeat=3, number=1000000, globals=None)

Executes setup once followed by a timing test. A timing test is number executions of stmnt. Repeat executing setup and the timing test repeat times (setup is only executed at the start of each time test). Can supply a dict object to specify the globals for the namespace that setup and stmt are executed in. All arguments are optional.

The setup and stmt arguments can be specified in two ways:

• As a string of Python statements to execute. Multiple statements in the string can be separated by ;.
• As an object that is callable without arguments.

The return value from the repeat function is a list of the execution time in seconds for each timing test.

For example, using the example code above and Python statements as strings:

>>> from timeit import repeat
>>> repeat(stmt='profile_me.main()', setup='import profile_me')
[15.187742052017711, 15.206103866017656, 15.189024122984847]

Again, but this time using a callable object without arguments:

>>> from timeit import repeat
>>> import profile_me
>>> repeat(stmt=profile_me.main)
[15.196357882989105, 15.172260118997656, 15.361751797958277]

It is also possible to call the timeit code from the command line using the following format:

python -m timeit [-n N] [-r N] [-s S] [statement ...]

Where:

• -n specifies the number of time to execute statement
• -r specifies the number of times to repeat the timing test
• -s specifies the setup statement

For example:

$ python3 -m timeit -n 1000000 -s 'import profile_me' 'profile_me.main()'
1000000 loops, best of 3: 15.1 usec per loop

Note

Unlike the output in the Python console, the output on the command line is the time it takes to execute stmt a single time (be sure to notice the change in units).

cProfile

If you are interested in more detail than the single execution time value you get with timeit, you can use the cProfile package to generate an execution time profile for the function calls that occur in your program.

Note

There is also the profile class, which is written in pure Python and may be easier to extend than cProfile. However, it adds a lot of overhead to the program being profiled and thus isn’t generally recommended for use.

The profiling operation can be started using the run method:

cProfile.run(command, filename=None, sort=-1)

This method will execute command (which must be written in a string), profile it, and print the statistics to the terminal (or to disk if filename is given).

Profiling the example code can be quickly done as shown below:

import profile_me
import cProfile

cProfile.run('profile_me.main(1000, 1000)')
     9 function calls in 0.142 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.007    0.007    0.142    0.142 <string>:1(<module>)
     1    0.112    0.112    0.112    0.112 profile_me.py:14(<listcomp>)
     1    0.000    0.000    0.022    0.022 profile_me.py:17(sum_coords)
     1    0.019    0.019    0.019    0.019 profile_me.py:24(<listcomp>)
     1    0.001    0.001    0.135    0.135 profile_me.py:28(main)
     1    0.000    0.000    0.112    0.112 profile_me.py:6(get_even_coords)
     1    0.000    0.000    0.142    0.142 {built-in method exec}
     1    0.004    0.004    0.004    0.004 {built-in method sum}
     1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

The columns have the following meaning:

• ncalls - The number of calls.
• tottime - The total time spent in the given function (and excluding time made in calls to sub-functions)
• percall - The quotient of tottime divided by ncalls
• cumtime - The cumulative time spent in this and all subfunctions (from invocation till exit). This figure is accurate even for recursive functions.
• percall - The quotient of cumtime divided by primitive calls
• filename:lineno(function) - Provides the respective data of each function

You can also invoke the profiler from the command line if you want using the following syntax:

python -m cProfile [-o output_file] [-s sort_order] myscript.py

Where:

• -o specifies the output file to dump the results to
• -s specifies how to sort the output (accepts one of the pstats.Stats.sort_stats() keys to sort on)

The pstats.Stats object can be used to sort the profile statistics returned by the cProfile.run() method. For example, to sort by total time:

import profile_me
import cProfile
import pstats

cProfile.run('profile_me.main(1000, 1000)', 'profile_results.txt')
stats = pstats.Stats('profile_results.txt')
stats.strip_dirs()
stats.sort_stats('tottime')
stats.print_stats()

      9 function calls in 0.148 seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.116    0.116    0.116    0.116 profile_me.py:14(<listcomp>)
     1    0.019    0.019    0.019    0.019 profile_me.py:24(<listcomp>)
     1    0.008    0.008    0.148    0.148 <string>:1(<module>)
     1    0.004    0.004    0.004    0.004 {built-in method sum}
     1    0.001    0.001    0.140    0.140 profile_me.py:28(main)
     1    0.000    0.000    0.148    0.148 {built-in method exec}
     1    0.000    0.000    0.023    0.023 profile_me.py:17(sum_coords)
     1    0.000    0.000    0.116    0.116 profile_me.py:6(get_even_coords)
     1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Consult the pstats.Stats documentation for further ways to sort.