How it Works logo pyinstrument: how it works

1 2 3 4 5 6 7

Pyinstrument is a statistical profiler. That means that it measures on an interval to record what function is being called. By repeating this many times on a short interval you should get a pretty good idea of where the most time is being spent ... but it won't be a perfect measurement.

Let's consider our example once more.

import time
from pyinstrument import Profiler

profiler = Profiler()
profiler.start()

sleep_time = 0.1

def start():
    time.sleep(sleep_time)
    do_sleep1()
    do_sleep2()

def do_sleep1():
    time.sleep(sleep_time)

def do_sleep2():
    do_sleep1()
    time.sleep(sleep_time)

start()

profiler.stop()
profiler.print()

This example runs just fine, but let's now change the sleep_time parameter to make it sleep for a very short period of time.

import time
from pyinstrument import Profiler

profiler = Profiler()
profiler.start()

sleep_time = 0.00001

def start():
    time.sleep(sleep_time)
    do_sleep1()
    do_sleep2()

def do_sleep1():
    time.sleep(sleep_time)

def do_sleep2():
    do_sleep1()
    time.sleep(sleep_time)

start()

profiler.stop()
profiler.print()

When you run this, the output will change severly!

Fix

To fix this, you can specify at what interval the profiler should measure.

import time
from pyinstrument import Profiler

# Note the interval value is 1/10th the sleeptime!
profiler = Profiler(interval=0.000001)
profiler.start()

sleep_time = 0.00001

def start():
    time.sleep(sleep_time)
    do_sleep1()
    do_sleep2()

def do_sleep1():
    time.sleep(sleep_time)

def do_sleep2():
    do_sleep1()
    time.sleep(sleep_time)

start()

profiler.stop()
profiler.print()

When we decrease the interval then we will collect many more samples. While this may be a good thing in some situations, we should be mindful that we may also increase the measurement overhead.

One can also wonder if spending effort to measure the shortest calls in our stack is going to help us achieve the biggest speedup.