Timing in Python: profiling

A common question for Python programmers is “how do I speed up …?”

In a previous article, I mentioned the importance of vectorization, modularity, variance, and coverage for performing timing tests. We assumed there was a single function that needed testing and used the timeit module to compare runtimes. In practice, we often don’t know in advance which parts of our code are slow; our tests should help determine the location of bottlenecks that need changing.

Example of a profile from https://github.com/gaogaotiantian/viztracer/blob/master/img/example.png

Do it for me

Python’s in-built profile and cProfile modules will profile your code for you.

from cProfile import Profile

with Profile() as profile:
  # code block to be timed, e.g.
  _ = list(range(10_000_000))
  # print the results sorted by the total (internal) time
  profile.print_stats('tottime')

Giving an output like:

         6960 function calls (6865 primitive calls) in 0.110 seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     5    0.068    0.014    0.069    0.014 <frozen importlib._bootstrap_external>:750(_compile_bytecode)
     7    0.018    0.003    0.018    0.003 {built-in method _io.open_code}
     1    0.007    0.007    0.007    0.007 {built-in method builtins.compile}
     6    0.002    0.000    0.002    0.000 {method 'read' of '_io.BufferedReader' objects}
     1    0.001    0.001    0.001    0.001 {built-in method nt.replace}
     5    0.001    0.000    0.001    0.000 {built-in method marshal.loads}
  14/1    0.001    0.000    0.082    0.082 {built-in method builtins.exec}
 63/62    0.001    0.000    0.003    0.000 {built-in method builtins.__build_class__}
   7/1    0.001    0.000    0.110    0.110 <frozen importlib._bootstrap>:1349(_find_and_load)

   ...

Which tells us that the most time is spent in _compile_bytecode.

Note that there is an overhead involved with tracing each of the functions, so it is not the most accurate measurement of the execution time. See also:

• pyinstrument: visualisation of call stacks
• py-spy: uses statistical sampling (low overhead) and attaches to running processes (no source code changes)
• scalene: includes memory profiling
• yappi: especially for multithreaded and async
• viztracer: supports threading, multiprocess, async, and GPU, either in-line or run as a no-source-code-change wrapper
• line_profiler : line-by-line level of detail
• codetiming: annotate your code in timed blocks using decorators or context managers

Write it yourself

To get more specific insights, insert timers into your code. Several of the above listed modules require or support adding timers to your code. Timing sections of your code is this simple:

from codetiming import Timer

# method1: context manager
with Timer():
  # code block to be timed, e.g.
  _ = list(range(10_000_000))

# method2: decorator
@Timer
def calculate(*args):
  # ...
  return

Decorators are useful for many purposes, and it’s worth using an example to see how they work:

import time
import numpy as np
import functools

def timed(f):
  """A decorator that times the function execution"""
  # decorator to transfer the name and description of f 
  @functools.wraps(f) 
  def wrapped(*args, **kwargs):
    t0 = time.perf_counter()
    result = f(*args, **kwargs)
    t1 = time.perf_counter()
    print(f'{f.__name__} took {t1-t0} s')
    return result
  return wrapped

@timed
def part0(shape1, shape2):
  return np.random.random(shape1), np.ones(shape2)

@timed
def part1(a, b):
  return np.concatenate((a,b))

@timed
def part2(a):
  result = 0
  for row in a:
    for x in row:
      result += x * x
  return result

if __name__ == "__main__":
  input_shapes = [(5, 10), (50, 100), (500, 1000), (5000, 10000)]
  for x, y in input_shapes:
    inp0, inp1 = part0((x,y), (2*x, y))
    tmp = part1(inp0, inp1)
    result = part2(tmp)

In this example, it’s quite obvious that part2 is the bottleneck, taking up ~95% of the runtime. So that’s where we should focus our efforts. And the solution is to vectorize:

def part2(a):
  return np.sum(a*a)

What time are you measuring?

We used [time.perf_counter](https://docs.python.org/3/library/time.html#time.perf_counter) to precisely measure the real-time duration between the start and end of the function (also called the wall-clock time). For multithreaded or multiprocessing programs, it’s useful to compare CPU usage with [thread_time](https://docs.python.org/3/library/time.html#time.thread_time) or [process_time](https://docs.python.org/3/library/time.html#time.process_time). Those show the breakdown of what is keeping each component of the program busy and allow you to investigate where the time is spent on the CPU, or I/O, or waiting. There are other tools that can profile and visualise those events, such as one of the modules mentioned above (e.g. pyinstrument or viztracer), or more generally, Score-P with Cube.

Image of the Cube GUI displaying a profile trace playback, from https://juliapackages.com/p/scorep

Conclusion

This was a quick look at some of the tools you can use for time profiling your Python code, assuming that the goal is to identify bottlenecks and choose where to focus on optimization.