Python: a quick cProfile recipe with pstats

2025-05-20 Artist’s interpretation of cProfile and pstats in use.

Python comes with two built-in profilers for measuring the performance of your code: cProfile and profile. They have the same API, but cProfile is a C extension, while profile is implemented in Python. You nearly always want to use cProfile, as it’s faster and doesn’t skew measurements as much.

By default, cProfile’s CLI profiles a command and displays its profile statistics afterwards. But that can be a bit limited, especially for reading large profiles or re-sorting the same data in different ways.

For more flexibility, cProfile can instead save the profile data to a file, which you can then read with the pstats module. This is my preferred way of using it, and this post covers a recipe for doing so, with a worked example.

The recipe

First, profile your script:

$ python -m cProfile -o profile <script> [args]

Replace <script> with the path to your Python file, and [args] with any arguments you want to pass to it. cProfile will run your script under its profiling machinery, saving the results to a file called profile, as specified by the -o option.

Second, view the profile file using pstats:

$ python -m pstats profile <<< $'sort cumtime\nstats 1000' | less

The pstats CLI provides a REPL for interacting with profile files, based on its Stats class. The CLI is oddly undocumented, but its help command lists the available commands.

The above command passes several commands to pstats in a string. The string uses the $ syntax, a Bash feature for C-style strings, allowing \n to represent a newline, passing two commands:

sort cumtime: Sort the output by cumulative time, largest first. This means the time spent in a function and all its callees.
stats 1000: Show the first 1,000 lines of the profile.

The output is passed to less, a common pager, allowing you to scroll through the results. Press q to quit when you’re done!

Profile a module

If you’re running a module instead of a script, add -m like:

$ python -m cProfile -o profile -m <module> [args]

Replace <module> with the name of the module you want to profile, and [args] with any arguments you want to pass to it.

Multiple profiles

If you’re profiling code before and after, consider using different profile file names instead of just profile. For example, for checking the results of some optimization, I often use the names before.profile and after.profile, like:

$ python -m cProfile -o before.profile example.py

$ git switch optimize_all_the_things

$ python -m cProfile -o after.profile example.py

Alternative sort orders

To sort by other metrics, swap cumtime in sort cumtime for one of these values, per the Stats.sort_stats() documentation:

time: internal time—the time spent in the function itself, excluding calls to other functions.

This is useful for finding the slowest functions in your code.
calls: number of calls to the function.

This is useful for finding functions that are called many times and may be candidates for optimization, such as caching.

A Djangoey example

Here’s a worked example showing how to apply this recipe to a Django management command. Say you are testing a database migration locally:

$ ./manage.py migrate example 0002
Operations to perform:
  Target specific migration: 0002_complexito, from example
Running migrations:
  Applying example.0002_complexito... OK

While it did pass, it was unexpectedly slow. To profile it, you would first reverse the migration to reset your test database:

$ ./manage.py migrate example 0001
...

Then you could apply the recipe to profile the migration.

First, stick the cProfile command in front of the migration command:

$ python -m cProfile -o profile ./manage.py migrate example 0002
Operations to perform:
  Target specific migration: 0002_complexito, from example
Running migrations:
  Applying example.0002_complexito... OK

Then, run the second pstats command to view the results:

$ python -m pstats profile <<< $'sort cumtime\nstats 1000' | less

This opens less with a long table, starting:

Welcome to the profile statistics browser.
profile% profile% Mon May 19 23:52:37 2025    profile

         213287 function calls (206021 primitive calls) in 1.150 seconds

   Ordered by: cumulative time
   List reduced from 3576 to 1000 due to restriction <1000>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   425/1    0.001    0.000    1.150    1.150 {built-in method builtins.exec}
       1    0.000    0.000    1.150    1.150 ./manage.py:1(<module>)
       1    0.000    0.000    1.150    1.150 ./manage.py:7(main)
       1    0.000    0.000    1.109    1.109 /.../django/core/management/__init__.py:439(execute_from_command_line)
   ...

The header tells us how many function calls were made, how many were primitive calls, and how long the code took to run. Then there’s the table of all function calls, limited to 1,000 entries.

Since we’re sorting by cumtime, cumulative time spent in each function, the first line shows the total time spent in all functions. That exec is cProfile running your code, and the later lines represent the top-level wrappers from Django.

Generally, it’s best to find the first listed function within your code base. In this profile, you would search for ``example/ and find this entry:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
...
    1    0.000    0.000    1.005    1.005 /.../example/migrations/0002_complexito.py:4(forward)
...

One call to the forward() function in the migration file took 1.005 seconds, nearly all of the 1.150 seconds total runtime. That’s a bit suspicious!

Right above that entry, you might also spot the time spent running queries:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
...
   13    0.000    0.000    1.007    0.077 /.../django/db/backends/utils.py:78(execute)
   13    0.000    0.000    1.007    0.077 /.../django/db/backends/utils.py:88(_execute_with_wrappers)
   13    0.000    0.000    1.007    0.077 /.../django/db/backends/utils.py:94(_execute)
   13    0.000    0.000    1.007    0.077 /.../django/db/backends/sqlite3/base.py:354(execute)
   13    1.006    0.077    1.006    0.077 {function SQLiteCursorWrapper.execute at 0x1054f7f60}
...

This stack of functions all show 13 calls, with a cumulative time of 1.007 or 1.006 seconds. They represent Django’s database backend wrappers, which eventually pass the query to Python’s SQLiteCursorWrapper.execute(), which is displayed differently because it’s implemented in C.

So, we can tell that the migration ran 13 queries in total, and at least one of them was slow and ran by forward(). At this point, you might look at the source of forward() to see if you can find the slow query. But first, you might want to re-display the profile to show only the forward() function and its callees (the functions it called), which might shed some light on what it was doing.

To show only forward() and its callees, you can use the pstats callees command. This takes a regular expression to match the function names you want to show:

$ python -m pstats profile <<< $'sort cumtime\ncallees \\bforward\\b' | less
Welcome to the profile statistics browser.
profile% profile%    Ordered by: cumulative time
   List reduced from 3576 to 1 due to restriction <'\\bforward\\b'>

Function
called...
ncalls  tottime  cumtime
/.../example/migrations/0002_complexito.py:4(forward)
  ->       1    0.000    0.000  /.../django/db/backends/utils.py:41(__enter__)
1    0.000    0.000  /.../django/db/backends/utils.py:44(__exit__)
1    0.000    1.005  /.../django/db/backends/utils.py:78(execute)
1    0.000    0.000  /.../django/utils/asyncio.py:15(inner)
1    0.000    0.000  {method 'create_function' of 'sqlite3.Connection' objects}

profile%
Goodbye.

(Output wrapped.)

This has revealed:

forward() only calls execute() once, so there’s only one slow query.
There’s also a call to SQLite’s create_function(). It’s fast, rounding down to 0.000 seconds, but perhaps may be something to do with the slow query.

Okay, time to look at the source:

def forward(apps, schema_editor):
    import time

    schema_editor.connection.connection.create_function(
        "sleep",
        1,
        time.sleep,
    )
    with schema_editor.connection.cursor() as cursor:
        cursor.execute("SELECT sleep(1)")

Ah, it’s a deliberate pause that I added to show you this example. Well, that solves that mystery.

Fin

May you cook up some great profiles with this recipe!

—Adam

😸😸😸 Check out my new book on using GitHub effectively, Boost Your GitHub DX! 😸😸😸

One summary email a week, no spam, I pinky promise.

Related posts:

Tags: python, django