How to Find Slow Python Code With the Python 3.15 Tachyon Sampling Profiler

A Python script that used to finish in a second now takes five, and nobody remembers changing anything. The usual reaction is to stare at the code and speed up whatever looks slow, which is a dependable way to spend a week improving a function that was never the problem. A profiler replaces that guesswork with measurements: it tells you where the time actually goes.

Python 3.15 ships a new profiler in the standard library, named Tachyon, in the module profiling.sampling. It is a sampling profiler. Instead of recording every function call, it looks at the call stack about a thousand times a second and counts what it finds. It can start your script for you, or attach to a program that is already running, and it needs no changes to your code.

In this tutorial you will profile a deliberately slow order report, find three separate hotspots, fix them one at a time, and prove each fix with timings, taking the script from 5.28 seconds to 0.08 seconds. Along the way you will learn how to read the output, why every percentage is an estimate, how wall-clock and CPU modes differ, how to attach to a process that is already running, how to save a profile as a flame graph and compare two profiles, and the places where a profile can mislead you. The commands and outputs below come from real runs on Python 3.15.0rc3.

Prerequisites

• Python 3.15. I used 3.15.0rc3, the release candidate dated October 2, 2026. The 3.15 release schedule in PEP 790 lists the final release for Friday, October 9, 2026. Output formats could shift slightly between a release candidate and the final, so expect small differences in spacing or wording.
• A terminal on Windows, macOS or Linux. I ran everything on Windows 11. Attaching to another process needs extra permissions on every platform; Step 11 covers that.
• Basic Python: functions, loops, dictionaries and reading a CSV file.
• pytest for a small safety-net test suite. Nothing else outside the standard library is required.
• About 45 minutes. The slow program takes five seconds per run, so most of that time is reading.

How a sampling profiler works

Before the first command, it helps to know what kind of tool you are about to use. A profiler is a program that measures where another program spends its time. The place where time piles up is called a hotspot. There are two main designs.

A tracing (or deterministic) profiler hooks every function call and return and times each one. Python has had these for a long time, cProfile being the best known. In 3.15 that tool lives in profiling.tracing, and the docs note that the module is “also available as cProfile for backward compatibility”. A sampling (or statistical) profiler instead looks at the program from outside at regular intervals and records what it was doing at that instant. The Tachyon documentation offers an analogy: “tracing is like having someone follow you and write down every step you take, while sampling is like taking photographs every second and inferring your path from those snapshots.”

Both now sit in one package. PEP 799 created the profiling package to “organize Python’s built-in profiling tools under a single, coherent namespace.”

Three terms will appear in every output you read:

• A stack is the chain of functions currently running: the main program called build_report, which called drop_duplicates, and so on.
• A sample is one look at that stack. At the default rate of 1 kHz the profiler takes about 1,000 samples per second, so each sample stands for roughly one millisecond.
• A sampling attempt can fail. If the profiler reads the target’s memory while the interpreter is in the middle of updating it, that attempt produces no sample.

Because the numbers come from counting samples, the docs are direct about what they are: “The time values shown in Tachyon’s output are estimates derived from sample counts, not direct measurements.” They also tell you where the tool is weak. “For very short scripts that complete in under one second, the profiler may not collect enough samples for reliable results,” and “When you need exact call counts, sampling cannot provide them.” Keep both limits in mind; Steps 8 and 13 test them.

Step 1: Check your Python and create the project

Open a terminal in an empty folder and confirm that you are running Python 3.15:

python --version

Python 3.15.0rc3

The profiler is a module named profiling.sampling, and it does not exist before 3.15. When I pointed Python 3.13.14 at it, the error was Error while finding module specification for 'profiling.sampling' (ModuleNotFoundError: No module named 'profiling'). If you see that message, you are running an older interpreter; use the full path to your 3.15 python executable for every command in this tutorial.

If you do not have 3.15 yet, download it from python.org. On Windows I used the 45 MB archive python-3.15.0rc3-amd64.zip from the python.org release folder. Unzipped, it gives a folder whose python.exe runs with no installer, and python -m ensurepip --upgrade adds pip. Then install the one dependency:

python -m pip install pytest

Step 2: Meet the slow program

You need something slow to measure. The first file generates a fake order export: 40,000 rows with an order ID, a timestamp, a region, a product code (SKU), a quantity and a price. About one row in ten repeats an earlier order, as happens when an export is run twice, and about two in a hundred have an invalid SKU. The random seed is fixed, so you get the same file every time.

# make_orders.py
import csv
import random
import sys
from datetime import datetime, timedelta


def make_orders(path, rows=15000, seed=11):
    rng = random.Random(seed)
    start = datetime(2026, 1, 1)
    regions = ["north", "south", "east", "west"]
    letters = "ABCDEFGHJKLMNPQRSTUVWXYZ"
    skus = [
        "".join(rng.choice(letters) for _ in range(3)) + "-" + f"{rng.randrange(10000):04d}"
        for _ in range(300)
    ]
    written = []
    with open(path, "w", newline="") as f:
        writer = csv.writer(f)
        writer.writerow(["order_id", "placed_at", "region", "sku", "qty", "unit_price"])
        for i in range(rows):
            if written and rng.random() < 0.10:
                row = rng.choice(written)  # the export repeated an earlier order
            else:
                when = start + timedelta(days=rng.randrange(90), seconds=rng.randrange(86400))
                sku = rng.choice(skus) if rng.random() > 0.02 else "BAD-SKU"
                row = [
                    f"ORD-{i:06d}",
                    when.strftime("%Y-%m-%d %H:%M:%S"),
                    rng.choice(regions),
                    sku,
                    rng.randint(1, 12),
                    f"{rng.uniform(3, 250):.2f}",
                ]
                written.append(row)
            writer.writerow(row)


if __name__ == "__main__":
    make_orders(sys.argv[1], rows=int(sys.argv[2]) if len(sys.argv) > 2 else 15000)

python make_orders.py orders.csv 40000

That writes a 2.2 MB file with 40,001 lines (a header plus 40,000 orders). Now the program we want to speed up:

# report.py
import csv
import re
import sys
import time
from datetime import datetime

SKU_PATTERN = r"^[A-Z]{3}-\d{4}$"


def is_valid_sku(sku):
    return re.match(SKU_PATTERN, sku) is not None


def parse_order(row):
    return {
        "order_id": row["order_id"],
        "placed_at": datetime.strptime(row["placed_at"], "%Y-%m-%d %H:%M:%S"),
        "region": row["region"],
        "sku": row["sku"],
        "qty": int(row["qty"]),
        "unit_price": float(row["unit_price"]),
    }


def read_orders(path):
    orders = []
    with open(path, newline="") as f:
        for row in csv.DictReader(f):
            if is_valid_sku(row["sku"]):
                orders.append(parse_order(row))
    return orders


def drop_duplicates(orders):
    seen_ids = []
    unique = []
    for order in orders:
        if order["order_id"] not in seen_ids:
            seen_ids.append(order["order_id"])
            unique.append(order)
    return unique


def daily_revenue(orders, region):
    days = sorted({o["placed_at"].date() for o in orders})
    totals = {}
    for day in days:
        total = 0.0
        for o in orders:
            if o["region"] == region and o["placed_at"].date() == day:
                total += o["qty"] * o["unit_price"]
        totals[day] = round(total, 2)
    return totals


def build_report(path):
    orders = drop_duplicates(read_orders(path))
    lines = [f"orders={len(orders)}"]
    for region in ("north", "south", "east", "west"):
        totals = daily_revenue(orders, region)
        best_day = max(totals, key=totals.get)
        lines.append(
            f"{region:<6} days={len(totals)} best={best_day} "
            f"best_revenue={totals[best_day]:,.2f} total={sum(totals.values()):,.2f}"
        )
    return "\n".join(lines)


if __name__ == "__main__":
    started = time.perf_counter()
    print(build_report(sys.argv[1]))
    print(f"elapsed {time.perf_counter() - started:.2f}s", file=sys.stderr)

Read it from the bottom up. The last block runs build_report and prints how long it took to standard error (stderr), so the timing never mixes with the report text we are going to compare. build_report reads the orders, drops duplicate order IDs, then for each region totals the revenue per day and prints the best day. Underneath, is_valid_sku checks the SKU format with a regular expression, parse_order converts one CSV row into a dictionary with real numbers and a real date, and read_orders streams the file.

Run it:

python report.py orders.csv

orders=35406
north  days=90 best=2026-02-17 best_revenue=109,081.34 total=7,278,633.35
south  days=90 best=2026-01-10 best_revenue=107,353.30 total=7,373,249.23
east   days=90 best=2026-02-23 best_revenue=107,225.78 total=7,309,734.70
west   days=90 best=2026-01-05 best_revenue=101,966.51 total=7,060,594.56
elapsed 5.28s

Five lines of report, then the timing. On my machine the script took 5.28 seconds (the median of three runs: 5.28, 5.31 and 5.19); yours will differ, so what matters is the ratios, not the absolute numbers. The first line says orders=35406: duplicates and bad SKUs removed, 35,406 orders remain. Save the report as the reference answer. The elapsed line goes to stderr, so it still prints in the terminal:

python report.py orders.csv > baseline.txt

Step 3: Write a safety net before you optimize

Making code faster is a refactor, and refactors break things quietly. Before touching anything, lock in what the report must do. This pytest file builds a tiny order file with a duplicate order, an invalid SKU, a day on which one region has no orders, and two regions with no orders at all, then pins the expected lines:

# test_report.py
import report

CSV_TEXT = """order_id,placed_at,region,sku,qty,unit_price
A1,2026-01-01 09:00:00,north,ABC-1234,2,10.00
A2,2026-01-01 10:00:00,south,ABC-1234,1,5.00
A3,2026-01-03 11:00:00,south,ABC-1234,3,5.00
A3,2026-01-03 11:00:00,south,ABC-1234,3,5.00
A4,2026-01-02 12:00:00,north,BAD-SKU,9,99.00
A5,2026-01-02 13:00:00,north,XYZ-9999,1,7.50
"""


def build(tmp_path):
    path = tmp_path / "orders.csv"
    path.write_text(CSV_TEXT, newline="")
    return report.build_report(str(path)).splitlines()


def test_duplicates_and_bad_skus_are_dropped(tmp_path):
    assert build(tmp_path)[0] == "orders=4"


def test_a_day_with_no_orders_counts_as_zero(tmp_path):
    lines = build(tmp_path)
    assert lines[2] == "south  days=3 best=2026-01-03 best_revenue=15.00 total=20.00"


def test_a_region_with_no_orders_reports_zero(tmp_path):
    lines = build(tmp_path)
    assert lines[3] == "east   days=3 best=2026-01-01 best_revenue=0.00 total=0.00"

A second tiny helper compares two files byte for byte, so we can check that the full report stays identical after every change:

# check_same.py
import filecmp
import sys

same = filecmp.cmp(sys.argv[1], sys.argv[2], shallow=False)
print("identical" if same else "DIFFERENT")
sys.exit(0 if same else 1)

python -m pytest -q

...                                                                      [100%]
3 passed in 0.05s

Three tests pass against the slow original. Keep them handy: they run in a twentieth of a second, so you can run them after every edit.

Step 4: Profile it for the first time

The run command starts your script under the profiler. Everything after the script name is passed to the script, just as if you had typed it yourself:

python -m profiling.sampling run report.py orders.csv

orders=35406
north  days=90 best=2026-02-17 best_revenue=109,081.34 total=7,278,633.35
south  days=90 best=2026-01-10 best_revenue=107,353.30 total=7,373,249.23
east   days=90 best=2026-02-23 best_revenue=107,225.78 total=7,309,734.70
west   days=90 best=2026-01-05 best_revenue=101,966.51 total=7,060,594.56
elapsed 5.37s
Captured 5,381 samples in 5.38 seconds
Sample rate: 999.98 samples/sec
Error rate: 1.67
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      4574/4574      86.5         4.574      86.5         4.574  report.py:39(drop_duplicates)
        556/556      10.5         0.556      10.5         0.556  report.py:51(daily_revenue)
          41/41       0.8         0.041       0.8         0.041  report.py:50(daily_revenue)
          38/71       0.7         0.038       1.3         0.071  report.py:18(parse_order)
          10/10       0.2         0.010       0.2         0.010  report.py:46(daily_revenue)
           6/81       0.1         0.006       1.5         0.081  report.py:31(read_orders)
            6/9       0.1         0.006       0.2         0.009  _strptime.py:548(_strptime)
            6/6       0.1         0.006       0.1         0.006  report.py:40(drop_duplicates)
           5/32       0.1         0.005       0.6         0.032  _strptime.py:844(_strptime_datetime_datetime)
            5/6       0.1         0.005       0.1         0.006  report.py:12(is_valid_sku)
         3/5289       0.1         0.003     100.0         5.289  report.py:72(<module>)
            3/3       0.1         0.003       0.1         0.003  ~:0(<GC>)
            3/3       0.1         0.003       0.1         0.003  csv.py:175(DictReader.__next__)
            3/3       0.1         0.003       0.1         0.003  _strptime.py:600(_strptime)
            3/3       0.1         0.003       0.1         0.003  _strptime.py:546(_strptime)

Legend:
  nsamples: Direct/Cumulative samples (direct executing / on call stack)
  sample%: Percentage of total samples this function was directly executing
  tottime: Estimated total time spent directly in this function
  cumul%: Percentage of total samples when this function was on the call stack
  cumtime: Estimated cumulative time (including time in called functions)
  filename:lineno(function): Function location and name

Summary of Interesting Functions:

Functions with Highest Direct/Cumulative Ratio (Hot Spots):
  1.000 direct/cumulative ratio, 86.6% direct samples: report.py:(drop_duplicates)
  1.000 direct/cumulative ratio, 11.5% direct samples: report.py:(daily_revenue)
  1.000 direct/cumulative ratio, 0.1% direct samples: ~:(<GC>)

Functions with Highest Call Frequency (Indirect Calls):
  5286 indirect calls, 100.0% total stack presence: report.py:(<module>)
  75 indirect calls, 1.5% total stack presence: report.py:(read_orders)
  33 indirect calls, 1.3% total stack presence: report.py:(parse_order)

The report prints first, because the profiler waits for the program to finish before it prints its own results. Then come three status lines. Captured 5,381 samples in 5.38 seconds and Sample rate: 999.98 samples/sec confirm the default of about 1 kHz. Error rate: 1.67 is the percentage of sampling attempts that failed (in the 3.15.0rc3 source it is the number of failed attempts divided by the number of attempts, times 100). The docs call the opposite number “sampling efficiency”, defined as “the percentage of sample attempts that succeeded.” An error rate of 1.67 percent is excellent; later you will see rates above 30 percent.

Read the table

Each row is a place in your code. The columns are:

The answer is on the first row. drop_duplicates had the top of the stack in 4,574 samples, 86.5 percent of the run, about 4.6 seconds. The next row, daily_revenue, accounts for most of the rest at 10.5 percent. Everything else, including the date parsing you might have suspected, is below 2 percent. If you had guessed, you would probably have started with the date parsing.

The legend and summary below the table are the profiler’s own hints. “Hot Spots” lists functions where nearly all samples are direct, meaning the time is spent in the function itself and not in something it calls. “Indirect Calls” lists orchestration code, like our <module> row, that is on the stack almost all the time but is rarely the top frame. Add --no-summary to hide the summary, and --limit 6 to keep only the top six rows; I use both from here on to keep outputs short. The docs say --no-summary suppresses both the summary and the legend, but on 3.15.0rc3 the legend still printed in my runs, and I trim it from the outputs below. --sort changes the order; the accepted values are listed by python -m profiling.sampling run --help.

Read the line numbers

Look at the number after the colon: report.py:39(drop_duplicates). The def drop_duplicates line is line 35 of the file, so 39 is not where the function starts. In these outputs the number is the line that was executing when the sample was taken, which is why one function can appear on several rows, as daily_revenue does, once per line where samples landed. Add those rows up to get the function’s total. Ask Python for line 39:

python -c "import linecache; print(linecache.getline('report.py', 39), end='')"

        if order["order_id"] not in seen_ids:

That is the culprit. seen_ids is a list, and in on a list compares against every element until it finds a match. With about 35,000 orders the list grows to about 35,000 entries, so the loop does hundreds of millions of comparisons in total. The profiler did not explain why the line is slow; it told you which line to think about.

Step 5: Fix the biggest hotspot and profile again

A set answers “have I seen this?” in roughly constant time instead of scanning. Replace drop_duplicates with this version, which differs by two small edits:

# report.py (replace drop_duplicates)
def drop_duplicates(orders):
    seen_ids = set()
    unique = []
    for order in orders:
        if order["order_id"] not in seen_ids:
            seen_ids.add(order["order_id"])
            unique.append(order)
    return unique

Run the tests and compare the full report with the reference, in that order, every time you change something:

python -m pytest -q
python report.py orders.csv > after.txt
python check_same.py baseline.txt after.txt

...                                                                      [100%]
3 passed in 0.04s

identical

The tests pass, the report is identical, and the elapsed line printed 0.63 seconds on all three of my runs (0.63, 0.64, 0.63), down from 5.28. Now profile again, because fixing the top row changes the ranking:

python -m profiling.sampling run --no-summary --limit 6 report.py orders.csv

Captured 662 samples in 0.66 seconds
Sample rate: 999.40 samples/sec
Error rate: 13.29
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        422/422      73.8       422.000      73.8       422.000  report.py:51(daily_revenue)
          38/75       6.6        38.000      13.1        75.000  report.py:18(parse_order)
          31/31       5.4        31.000       5.4        31.000  report.py:50(daily_revenue)
            8/8       1.4         8.000       1.4         8.000  report.py:46(daily_revenue)
           7/85       1.2         7.000      14.9        85.000  report.py:31(read_orders)
            6/9       1.0         6.000       1.6         9.000  _strptime.py:548(_strptime)

daily_revenue is now the story: line 51 alone holds 73.8 percent of the samples. Line 51 is the if inside the innermost loop:

            if o["region"] == region and o["placed_at"].date() == day:

Look at what the code around it does. For every region (4), for every day (90), it scans all 35,406 orders and tests two conditions. That is 4 × 90 × 35,406, about 12.7 million passes through that line, to compute 360 totals. A profiler finds the line; reading the loop structure tells you the fix.

Step 6: Fix the next hotspot, and let a test catch a mistake

Instead of asking each region and day to search the whole list, make one pass over the orders and add each order to its bucket. Replace daily_revenue and build_report with this first attempt:

# report.py (delete daily_revenue and build_report, then add these two)
def revenue_by_region_and_day(orders):
    totals = {}
    for o in orders:
        key = (o["region"], o["placed_at"].date())
        totals[key] = totals.get(key, 0.0) + o["qty"] * o["unit_price"]
    return totals


def build_report(path):
    orders = drop_duplicates(read_orders(path))
    totals = revenue_by_region_and_day(orders)
    lines = [f"orders={len(orders)}"]
    for region in ("north", "south", "east", "west"):
        by_day = {day: round(v, 2) for (r, day), v in sorted(totals.items()) if r == region}
        best_day = max(by_day, key=by_day.get)
        lines.append(
            f"{region:<6} days={len(by_day)} best={best_day} "
            f"best_revenue={by_day[best_day]:,.2f} total={sum(by_day.values()):,.2f}"
        )
    return "\n".join(lines)

Before measuring anything, run the tests:

python -m pytest -q --tb=short

FFF                                                                      [100%]
================================== FAILURES ===================================
__________________ test_duplicates_and_bad_skus_are_dropped ___________________
test_report.py:21: in test_duplicates_and_bad_skus_are_dropped
    assert build(tmp_path)[0] == "orders=4"
           ^^^^^^^^^^^^^^^
test_report.py:17: in build
    return report.build_report(str(path)).splitlines()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
report.py:59: in build_report
    best_day = max(by_day, key=by_day.get)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
E   ValueError: max() iterable argument is empty

All three tests fail the same way. The new code only knows about the days it saw orders for, so a region with no orders at all, like east and west in the test file, produces an empty dictionary and max() has nothing to choose from. The old code looped over every day in the dataset, so it never had that problem. The short summary shows all three:

FAILED test_report.py::test_duplicates_and_bad_skus_are_dropped - ValueError:...
FAILED test_report.py::test_a_day_with_no_orders_counts_as_zero - ValueError:...
FAILED test_report.py::test_a_region_with_no_orders_reports_zero - ValueError...
3 failed in 0.08s

It is worth noticing what would have happened without the test. On the real 40,000-row file every region has orders on every one of the 90 days, so this broken version prints exactly the same report as the original; the full-file comparison would have passed. Only the small, deliberately awkward test file exposes the difference. Fix it by collecting the full list of days once and looking up each (region, day) pair with a default of zero:

# report.py (replace build_report again)
def build_report(path):
    orders = drop_duplicates(read_orders(path))
    totals = revenue_by_region_and_day(orders)
    days = sorted({o["placed_at"].date() for o in orders})
    lines = [f"orders={len(orders)}"]
    for region in ("north", "south", "east", "west"):
        by_day = {day: round(totals.get((region, day), 0.0), 2) for day in days}
        best_day = max(by_day, key=by_day.get)
        lines.append(
            f"{region:<6} days={len(by_day)} best={best_day} "
            f"best_revenue={by_day[best_day]:,.2f} total={sum(by_day.values()):,.2f}"
        )
    return "\n".join(lines)

python -m pytest -q
python report.py orders.csv > after.txt
python check_same.py baseline.txt after.txt

...                                                                      [100%]
3 passed in 0.04s

identical

Tests pass, report identical, and the elapsed line now says 0.19 seconds on all three runs. Profile once more:

python -m profiling.sampling run --no-summary --limit 6 report.py orders.csv

Captured 202 samples in 0.20 seconds
Sample rate: 995.47 samples/sec
Error rate: 38.12
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
          43/92      35.0        43.000      74.8        92.000  report.py:18(parse_order)
           9/13       7.3         9.000      10.6        13.000  _strptime.py:548(_strptime)
           7/45       5.7         7.000      36.6        45.000  _strptime.py:844(_strptime_datetime_datetime)
           4/99       3.3         4.000      80.5        99.000  report.py:31(read_orders)
            4/4       3.3         4.000       3.3         4.000  ~:0(<GC>)
            4/4       3.3         4.000       3.3         4.000  _strptime.py:600(_strptime)

Line 18 of parse_order is the line that calls datetime.strptime. Its direct share is 35.0 percent, but its cumulative share is 74.8 percent, and the rows below it are _strptime.py functions from the standard library. That gap is the cumulative column doing its job: parse_order was on the stack in three of every four samples, and most of that time was spent in helpers it called, not in its own line.

Step 7: Fix the third hotspot

datetime.strptime interprets a format string on every call, which is flexible and slow. Our timestamps are already in a standard layout (2026-01-05 13:45:10), and datetime.fromisoformat parses that directly. Replace parse_order:

# report.py (replace parse_order)
def parse_order(row):
    return {
        "order_id": row["order_id"],
        "placed_at": datetime.fromisoformat(row["placed_at"]),
        "region": row["region"],
        "sku": row["sku"],
        "qty": int(row["qty"]),
        "unit_price": float(row["unit_price"]),
    }

python -m pytest -q
python report.py orders.csv > after.txt
python check_same.py baseline.txt after.txt

...                                                                      [100%]
3 passed in 0.04s

identical

Tests pass, the report is still byte-identical (which also shows fromisoformat accepts our space-separated timestamps), and the script now finishes in 0.08 seconds. Here are all the versions side by side, each the median of three runs on the 40,000-row file:

That is roughly a 65-fold speedup (the elapsed line has two decimals, so 0.08 could be anything from 0.075 to 0.085). Now profile version 4 and look closely, because this is where a sampling profiler starts to need careful handling.

Step 8: Know when to stop, and how many samples you need

python -m profiling.sampling run --no-summary --limit 6 report.py orders.csv

Captured 95 samples in 0.10 seconds
Sample rate: 998.20 samples/sec
Error rate: 41.05
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
            8/8      14.8         8.000      14.8         8.000  csv.py:175(DictReader.__next__)
           5/22       9.3         5.000      40.7        22.000  report.py:29(read_orders)
            5/5       9.3         5.000       9.3         5.000  report.py:22(parse_order)
            4/7       7.4         4.000      13.0         7.000  csv.py:183(DictReader.__next__)
            3/3       5.6         3.000       5.6         3.000  ~:0(<GC>)
            3/3       5.6         3.000       5.6         3.000  report.py:12(is_valid_sku)

Only 95 samples. The error rate is 41 percent, and the top row has 8 samples, 14.8 percent of the total. This is the case the docs warned about: a program that finishes in under a second. To see how unstable such a profile is, here is a script that runs the profiler five times and prints the sample count and the three biggest rows each time. It saves each run with -o and reads it back with the standard pstats module; the profiler writes a binary pstats file when you give it an output path:

# repeat_profile.py
import pathlib
import pstats
import subprocess
import sys


def profile_once(script_args, extra=()):
    cmd = [sys.executable, "-m", "profiling.sampling", "run", "-o", "run.pstats", *extra, *script_args]
    subprocess.run(cmd, capture_output=True, check=True)
    stats = pstats.Stats("run.pstats").stats  # {(file, line, function): (nsamples, ...)}
    total = sum(row[0] for row in stats.values())
    top = sorted(stats.items(), key=lambda item: item[1][0], reverse=True)[:3]
    labels = [
        f"{pathlib.Path(file).name}:{line}({func}) {row[0] / total * 100:.0f}%"
        for (file, line, func), row in top
    ]
    return total, labels


if __name__ == "__main__":
    runs, extra = int(sys.argv[1]), sys.argv[2].split() if sys.argv[2] != "-" else []
    for i in range(1, runs + 1):
        total, labels = profile_once(sys.argv[3:], extra)
        print(f"run {i}: {total:>5} samples | " + " | ".join(labels))

python repeat_profile.py 5 - report.py orders.csv

run 1:    59 samples | csv.py:183(DictReader.__next__) 17% | csv.py:175(DictReader.__next__) 14% | report.py:18(parse_order) 8%
run 2:    54 samples | csv.py:183(DictReader.__next__) 15% | report.py:12(is_valid_sku) 15% | ~:0(<GC>) 7%
run 3:    55 samples | report.py:12(is_valid_sku) 18% | csv.py:175(DictReader.__next__) 11% | report.py:16(parse_order) 9%
run 4:    49 samples | report.py:12(is_valid_sku) 14% | csv.py:175(DictReader.__next__) 12% | report.py:18(parse_order) 12%
run 5:    66 samples | report.py:12(is_valid_sku) 15% | csv.py:175(DictReader.__next__) 14% | report.py:16(parse_order) 11%

The sample counts run from 49 to 66, and the leading row changes: DictReader.__next__ on line 183 in the first two runs (tied with is_valid_sku in the second), then is_valid_sku in the last three. Nothing in these five runs is strong enough to act on. The docs say as much: “Because sampling is statistical, results will vary slightly between runs.” The cure is more samples. The -r option raises the sampling rate; the second argument to my script passes it through:

python repeat_profile.py 5 "-r 10khz" report.py orders.csv

run 1:   575 samples | report.py:12(is_valid_sku) 14% | csv.py:175(DictReader.__next__) 12% | csv.py:183(DictReader.__next__) 10%
run 2:   572 samples | report.py:12(is_valid_sku) 14% | csv.py:183(DictReader.__next__) 13% | csv.py:175(DictReader.__next__) 10%
run 3:   606 samples | report.py:12(is_valid_sku) 15% | csv.py:175(DictReader.__next__) 12% | ~:0(<GC>) 8%
run 4:   621 samples | csv.py:175(DictReader.__next__) 12% | report.py:12(is_valid_sku) 12% | csv.py:183(DictReader.__next__) 11%
run 5:   607 samples | report.py:12(is_valid_sku) 17% | csv.py:183(DictReader.__next__) 16% | csv.py:175(DictReader.__next__) 10%

At 10 kHz each run holds 572 to 621 samples, about ten times more than at 1 kHz, and the same rows keep appearing, is_valid_sku and the two DictReader.__next__ lines (in run 3 a <GC> row takes the place of one of them), each between 8 and 17 percent. That is a flat profile: no single row dominates. For a bigger, steadier sample I made a ten-times larger input and profiled that:

python make_orders.py orders_big.csv 400000
python -m profiling.sampling run --no-summary --limit 6 report.py orders_big.csv

elapsed 0.93s
Captured 934 samples in 0.93 seconds
Sample rate: 999.66 samples/sec
Error rate: 32.33
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
          78/79      12.4        78.000      12.5        79.000  csv.py:175(DictReader.__next__)
          70/85      11.1        70.000      13.5        85.000  report.py:12(is_valid_sku)
         66/112      10.5        66.000      17.7       112.000  csv.py:183(DictReader.__next__)
          48/48       7.6        48.000       7.6        48.000  ~:0(<GC>)
          40/40       6.3        40.000       6.3        40.000  report.py:49(revenue_by_region_and_day)
          39/40       6.2        39.000       6.3        40.000  report.py:16(parse_order)

The program ran in 0.93 seconds under the profiler (0.89 seconds without it, as you will see shortly), and the top three rows are within two points of each other: two lines of CSV reading in csv.py and the SKU regular expression, followed by garbage collection (the <GC> row, which the profiler adds when collection is running). A flat profile is the signal to stop hunting for a big win. No single line is worth a rewrite, and any large further gain would mean a different approach, such as a faster CSV parser.

Step 9: Check a noisy profile with blocking mode

Look again at the last output: Error rate: 32.33. Nearly a third of the sampling attempts failed. The docs explain why attempts fail and give a remedy. By default the profiler reads the target’s memory while it keeps running, and that “can occasionally produce incomplete or inconsistent stack traces in applications with many generators or coroutines” or “very fast-changing call stacks.” The --blocking option pauses the target for each sample so the stack is always consistent, at the price of slowing the program. The docs advise using it only “when you observe inconsistent stacks in your profiles,” and a high error rate on a flat profile is a reasonable time to try it:

python -m profiling.sampling run --blocking --no-summary --limit 6 report.py orders_big.csv

elapsed 1.11s
Captured 1,119 samples in 1.12 seconds
Sample rate: 1,000.00 samples/sec
Error rate: 0.89
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        262/265      23.7       262.000      24.0       265.000  csv.py:175(DictReader.__next__)
        161/229      14.6       161.000      20.7       229.000  csv.py:183(DictReader.__next__)
         86/140       7.8        86.000      12.7       140.000  __init__.py:166(prefixmatch)
          73/73       6.6        73.000       6.6        73.000  ~:0(<GC>)
          50/50       4.5        50.000       4.5        50.000  report.py:16(parse_order)
          47/47       4.2        47.000       4.2        47.000  report.py:18(parse_order)

Three things changed. The error rate fell from 32.33 to 0.89 percent. The program slowed from 0.93 to 1.11 seconds, about 19 percent, which is the cost of stopping it for every sample. And the ranking changed: csv.py line 175 rises from 12 to 24 percent, and a row for prefixmatch in the re package appears, which is the regular expression call that is_valid_sku makes (in 3.15 re.match is an alias of re.prefixmatch, which is why the row has that name). Both runs agree on the overall message (CSV reading and the regular expression are the top costs, and nothing else is large), but they do not agree on the exact order. I cannot tell from the docs whether failed attempts are spread evenly across the program, so treat a profile with a high error rate as a rough guide and check it with --blocking before you invest in a change.

One last experiment shows the right way to use a flat profile: guess a cheap fix, then time it. Compiling the regular expression once at import time avoids a lookup on every call:

# report.py (replace SKU_PATTERN and is_valid_sku)
SKU_RE = re.compile(r"^[A-Z]{3}-\d{4}$")


def is_valid_sku(sku):
    return SKU_RE.match(sku) is not None

On the 400,000-row file I ran each version ten times, in two alternating blocks of five so that neither enjoyed a warmer cache. Version 4 had a median of 0.89 seconds and version 5 a median of 0.80 seconds, about 10 percent faster, with every run of each version within 0.01 seconds of its median. A small, real gain. Use the profiler to choose where to look and a plain timing to decide whether the change worked.

Step 10: Separate waiting from computing with wall-clock and CPU modes

The report was slow because it computed too much. Many real programs are slow because they wait: for a database, a web service or a disk. By default Tachyon runs in wall-clock mode, which counts a sample whether the thread is computing or sleeping. The --mode cpu option keeps only samples where the thread is actually running on a processor. This tiny program waits 1.5 seconds, standing in for a slow network call, and then computes:

# wait_or_work.py
import time


def wait_for_service():
    time.sleep(1.5)  # stands in for a slow network call


def crunch_numbers():
    return sum(i * i for i in range(5_000_000))


def main():
    wait_for_service()
    crunch_numbers()


if __name__ == "__main__":
    main()

python -m profiling.sampling run --no-summary --limit 5 wait_or_work.py

Captured 1,682 samples in 1.68 seconds
Sample rate: 999.91 samples/sec
Error rate: 3.75
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1498/1498      92.6         1.498      92.6         1.498  wait_or_work.py:6(wait_for_service)
         67/120       4.1         0.067       7.4         0.120  wait_or_work.py:10(crunch_numbers)
          53/53       3.3         0.053       3.3         0.053  wait_or_work.py:10(crunch_numbers.<locals>.<genexpr>)
         0/1498       0.0         0.000      92.6         1.498  wait_or_work.py:14(main)
         0/1618       0.0         0.000     100.0         1.618  wait_or_work.py:19(<module>)

In wall-clock mode wait_for_service holds 92.6 percent of the samples, and the computation barely registers. Now the same program in CPU mode:

python -m profiling.sampling run --mode cpu --no-summary --limit 5 wait_or_work.py

Captured 1,683 samples in 1.69 seconds
Sample rate: 998.79 samples/sec
Error rate: 3.74
Warning: missed 2 samples from the expected total of 1685 (0.12%)
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
         77/121      63.6        77.000     100.0       121.000  wait_or_work.py:10(crunch_numbers)
          44/44      36.4        44.000      36.4        44.000  wait_or_work.py:10(crunch_numbers.<locals>.<genexpr>)
          0/121       0.0         0.000     100.0       121.000  wait_or_work.py:15(main)
          0/121       0.0         0.000     100.0       121.000  wait_or_work.py:19(<module>)
          0/121       0.0         0.000     100.0       121.000  <frozen runpy>:87(_run_code)

The sleeping disappears. Notice that the profiler still captured 1,683 samples, but only 121 were recorded as the thread being on a CPU, and the percentages are relative to those 121. The docs spell out how to read the pair: “If a function is high in wall-clock mode but low or absent in CPU mode, it is I/O-bound or waiting.” Optimizing the arithmetic would not help this script; shortening the wait would. Run both modes whenever you are unsure which kind of slow you have. The docs describe two more modes, gil and exception; I did not test them here.

Step 11: Profile a program that is already running

The feature that makes a sampling profiler so useful in practice is attaching to a process you cannot restart. The profiler needs the process ID (PID), the number the operating system gave the program. Here is a worker that loops forever, checks whether a user exists in a 20,000-item list, hashes a block of data, and prints its own PID when it starts:

# worker.py
import hashlib
import os
import time

USERS = [f"user-{i}" for i in range(20000)]


def is_known_user(name):
    return name in USERS


def checksum_block(block):
    return hashlib.sha256(block).hexdigest()


def main():
    print(f"worker started, pid {os.getpid()}", flush=True)
    handled = 0
    while True:
        is_known_user("user-19999")
        checksum_block(b"x" * 4000)
        handled += 1
        if handled % 50 == 0:
            time.sleep(0.01)


if __name__ == "__main__":
    main()

In one terminal, start it:

python worker.py

worker started, pid 21488

In a second terminal, attach for three seconds, using the PID that your worker printed (mine was 21488):

python -m profiling.sampling attach -d 3 --no-summary --limit 5 21488

Captured 3,000 samples in 3.00 seconds
Sample rate: 999.96 samples/sec
Error rate: 0.43
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1785/1785      59.8         1.785      59.8         1.785  worker.py:25(main)
      1180/1180      39.5         1.180      39.5         1.180  worker.py:10(is_known_user)
          19/19       0.6         0.019       0.6         0.019  worker.py:14(checksum_block)
         2/1181       0.1         0.002      39.5         1.181  worker.py:21(main)
            1/1       0.0         0.001       0.0         0.001  worker.py:13(checksum_block)

-d 3 limits the profile to three seconds; without it, attach keeps sampling until the target exits or you interrupt it. The worker kept running the whole time. Line 25 of main is the time.sleep(0.01) call, so 59.8 percent of wall-clock time is the worker sleeping, and 39.5 percent is is_known_user. That is a lot of idle time, so ask the CPU-mode question:

python -m profiling.sampling attach --mode cpu -d 3 --no-summary --limit 5 21488

Captured 2,956 samples in 3.00 seconds
Sample rate: 984.89 samples/sec
Error rate: 0.41
Warning: missed 45 samples from the expected total of 3001 (1.50%)
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1437/1437      92.7         1.437      92.7         1.437  worker.py:10(is_known_user)
        95/1532       6.1         0.095      98.8         1.532  worker.py:21(main)
          14/14       0.9         0.014       0.9         0.014  worker.py:14(checksum_block)
           4/18       0.3         0.004       1.2         0.018  worker.py:22(main)
         0/1550       0.0         0.000     100.0         1.550  worker.py:29(<module>)

When the worker is actually working, 92.7 percent of its time is the list scan in is_known_user. The fix would be the same one you made in Step 5: keep the users in a set.

The dump command is the quick version, a single snapshot instead of a sampling loop. The docs say it is useful for investigating “hung or unresponsive processes” and prints something that looks like a traceback:

python -m profiling.sampling dump --blocking 21488

Stack dump for PID 21488, thread 11712 (main thread, has GIL; most recent call last):
  File "worker.py", line 29, in <module>
    main()
  File "worker.py", line 21, in main
    is_known_user("user-19999")
  File "worker.py", line 10, in is_known_user
    return name in USERS

I added --blocking on purpose. Without it, dump reads the busy worker while it keeps running, and on my machine 3 of 20 plain calls failed with RuntimeError: Failed to parse initial frame in chain. (Earlier tests of the same kind gave 3 failures in 6 and 1 in 10, so the rate is not constant.) With --blocking, 20 of 20 succeeded. The docs predict this: without the flag dump “can occasionally produce a torn stack.” If a plain dump fails, run it again with --blocking.

Permissions and version rules

Reading another process’s memory is a privileged operation, and the docs list the requirement per platform. On Windows: “the profiler requires administrative privileges or the SeDebugPrivilege privilege to read another process’s memory.” On Linux the profiler “uses ptrace or process_vm_readv,” which usually means running as root, holding the CAP_SYS_PTRACE capability, or relaxing the Yama ptrace_scope setting. On macOS it “uses task_for_pid()” for the same purpose. My Windows account is an administrator, so I could not test the failure case. There is also a version rule: the profiler and target “must run the same Python minor version,” and if either one is a pre-release, “both must run the exact same version.” If your attach fails with a version complaint, check that both sides report the identical python --version.

Step 12: Save, share and compare profiles

A table in a terminal is fine for yourself. For a colleague or a pull request, Tachyon can write several other formats. I produced each one from version 1 of the report (the slow one), so there is something to see.

An interactive flame graph

python -m profiling.sampling run --flamegraph -o flame_v1.html report.py orders.csv

Captured 5,698 samples in 5.70 seconds
Sample rate: 999.89 samples/sec
Error rate: 1.60
Flamegraph data: 1 root function, 5600 total samples, 99 unique strings
Flamegraph saved to: flame_v1.html

The result is one self-contained HTML file, 636,896 bytes on my machine, that opens in any browser. I opened an equivalent run of this command in Edge. The main area is a stack of horizontal bars: the entry point at the top, then <module>, then build_report, and below that the functions it called, each bar as wide as its share of the samples. drop_duplicates fills almost the whole width, with daily_revenue a small block at the right end. The sidebar has a profile summary (sample count, duration, samples per second), the sampling-efficiency percentage (98.2 percent for the run I opened, which matches an error rate of about 1.7), and a numbered hotspot list headed by drop_duplicates at about 85 percent. There is a search box, a toggle between file paths and module names, and an inverted view.

Collapsed stacks and the heatmap

python -m profiling.sampling run --collapsed -o stacks.txt report.py orders.csv

The collapsed format has one line per distinct stack, a semicolon between frames and a sample count at the end. The docs say it is designed for compatibility with external flame graph tools, particularly Brendan Gregg’s flamegraph.pl; I did not run that script. The file had 41 lines; these are the three most-sampled stacks, each starting with a thread ID:

tid:9228;<frozen runpy>:_run_module_as_main:201;<frozen runpy>:_run_code:87;report.py:<module>:72;report.py:build_report:58;report.py:drop_duplicates:39 4457
tid:9228;<frozen runpy>:_run_module_as_main:201;<frozen runpy>:_run_code:87;report.py:<module>:72;report.py:build_report:61;report.py:daily_revenue:51 563
tid:9228;<frozen runpy>:_run_module_as_main:201;<frozen runpy>:_run_code:87;report.py:<module>:72;report.py:build_report:61;report.py:daily_revenue:50 40

The heatmap overlays sample counts on your source code, line by line:

python -m profiling.sampling run --heatmap -o heat_v1 report.py orders.csv

Heatmap output written to heat_v1/
  - Index: heat_v1\index.html
  - 4 source files analyzed

It wrote a folder with an index.html and one page per source file that appeared in the samples, including standard library files such as _strptime.py:

file_0000.html
file_0001.html
file_0002.html
file_0003.html
index.html

Binary profiles and replay

python -m profiling.sampling run --binary -o base.bin report.py orders.csv
python -m profiling.sampling replay --no-summary --limit 3 base.bin

Replaying 5275 samples from base.bin
  Sample interval: 1000 us
  Compression: none

Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      4603/4603      87.3         4.603      87.3         4.603  report.py:39(drop_duplicates)
        499/499       9.5         0.499       9.5         0.499  report.py:51(daily_revenue)
          48/48       0.9         0.048       0.9         0.048  report.py:50(daily_revenue)

The binary file was 27,776 bytes against 636,896 for the flame graph of the same run. You capture once and convert later to other formats with replay, without profiling again. (A progress bar prints between the first lines and the table; I removed it here.) The replay reports 5,275 samples although the run captured 5,360 attempts: the difference is the failed attempts, which are not stored.

A differential flame graph, and a trap

The binary file has a second use. Make a change to the program, profile it with --diff-flamegraph and the old binary file, and the new flame graph is colored by what changed. I swapped in the Step 5 version of the report as report.py and ran:

python -m profiling.sampling run --diff-flamegraph base.bin -o diff_v1_v2.html report.py orders.csv

elapsed 0.65s
Captured 661 samples in 0.66 seconds
Sample rate: 999.27 samples/sec
Error rate: 13.31
Flamegraph data: 1 root function, 571 total samples, 301 unique strings
Flamegraph saved to: diff_v1_v2.html

The docs describe the colors: red marks “Functions consuming more time (regressions)” and blue the opposite. In an earlier run of the same comparison I opened the page and found almost everything red or gray, with only thin blue slivers, for a program that had just become eight times faster. The reason is in the code. The 3.15.0rc3 source scales the baseline before comparing (scale = current_time / baseline_time), so both profiles are treated as if they had the same total duration. The page’s own data confirms it:

baseline_samples: 5273
current_samples: 571
baseline_scale: 0.10828750237056704

That scale, 0.1083 when rounded, is 571 divided by 5,273. A function that went from 10.5 percent of the long run (556 samples) to 73.8 percent of the short one (422 samples) is painted red, even though it got less total time. So read the colors as a change in each function’s share of the run. The differential graph is most reliable when the two runs do roughly the same total work, which fits its intended use, hunting a regression between two similar builds. It is a poor way to celebrate an eight-fold speedup.

Reading profiles from your own code

The pstats file that repeat_profile.py reads back is a normal pstats file: pstats.Stats loaded it in my tests (as a SampledStats object) and print_stats printed its rows. The command-line help also lists a --jsonl option, described as “Generate newline-delimited JSON (JSONL) for programmatic consumers” and I did not test it.

Step 13: See why Tachyon exists, tracing versus sampling

You now have a feel for the sampling profiler. The obvious question is why not use cProfile, which has existed for decades. This script answers it. It has one function called three million times, which does almost nothing, and a sort that runs only twelve times but does real work. It times each phase itself:

# tiny_calls.py
import time


def square(x):
    return x * x


def sum_of_squares(n):
    total = 0
    for i in range(n):
        total += square(i)
    return total


def sort_blocks(blocks, size):
    data = [(i * 7919) % 100003 for i in range(size)]
    for _ in range(blocks):
        sorted(data)


if __name__ == "__main__":
    t0 = time.perf_counter()
    sum_of_squares(3_000_000)
    t1 = time.perf_counter()
    sort_blocks(blocks=12, size=300_000)
    t2 = time.perf_counter()
    print(f"sum_of_squares {t1 - t0:.3f}s  sort_blocks {t2 - t1:.3f}s  total {t2 - t0:.3f}s")

First, with no profiler, to learn the truth (median of three runs):

python tiny_calls.py

sum_of_squares 0.110s  sort_blocks 0.181s  total 0.290s

Then under Tachyon, and under the tracing profiler (profiling.tracing, the new home of cProfile):

python -m profiling.sampling run --no-summary --limit 6 tiny_calls.py
python -m profiling.tracing -s tottime tiny_calls.py

sum_of_squares 0.122s  sort_blocks 0.191s  total 0.312s
Captured 320 samples in 0.32 seconds
Sample rate: 999.02 samples/sec
Error rate: 10.31
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        175/175      61.6       175.000      61.6       175.000  tiny_calls.py:19(sort_blocks)
          58/80      20.4        58.000      28.2        80.000  tiny_calls.py:12(sum_of_squares)
          21/21       7.4        21.000       7.4        21.000  tiny_calls.py:6(square)
          15/15       5.3        15.000       5.3        15.000  tiny_calls.py:17(sort_blocks)
          12/13       4.2        12.000       4.6        13.000  tiny_calls.py:11(sum_of_squares)
            2/2       0.7         2.000       0.7         2.000  tiny_calls.py:5(square)

sum_of_squares 0.488s  sort_blocks 0.183s  total 0.670s
         3000021 function calls in 0.670 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.334    0.334    0.488    0.488 tiny_calls.py:9(sum_of_squares)
       12    0.161    0.013    0.161    0.013 {built-in method builtins.sorted}
  3000000    0.154    0.000    0.154    0.000 tiny_calls.py:5(square)
        1    0.020    0.020    0.181    0.181 tiny_calls.py:16(sort_blocks)
        1    0.001    0.001    0.670    0.670 tiny_calls.py:1(<module>)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.670    0.670 {built-in method builtins.exec}
        3    0.000    0.000    0.000    0.000 {built-in method time.perf_counter}

The program prints its own phase timings first, so the cost of each profiler is visible. These are the medians of three runs:

plain    sum_of_squares 0.110s  sort_blocks 0.180s  total 0.290s  (median of 3)
tachyon  sum_of_squares 0.116s  sort_blocks 0.191s  total 0.307s  (median of 3)
tracing  sum_of_squares 0.486s  sort_blocks 0.183s  total 0.669s  (median of 3)

Tachyon added about 6 percent to the total (0.290 to 0.307 seconds), a little more than the docs’ phrase “overhead is virtually zero” suggests, though with only three runs per tool I would treat 6 percent as a rough figure. The tracing profiler made the program 2.3 times slower, and nearly all of the extra time landed in the phase with three million calls: sum_of_squares grew from 0.110 to 0.486 seconds while the sort stayed at 0.18. Now compare what each tool tells you about where the time goes:

The shares come from one run of each tool (Tachyon: the rows for sum_of_squares and square against the rows for sort_blocks; tracing: tottime for sum_of_squares and square against sorted and sort_blocks). Tachyon is within about five points of the truth. The tracing profiler inverts the ranking, because its cost is proportional to the number of calls, so it blames the code that makes many cheap calls. The PEP that created the package says the tracing method “introduces significant runtime overhead and can disable certain interpreter optimizations,” and the table is that overhead in action. Tracing does give you something sampling cannot: it counted exactly 3,000,000 calls of square. Pick the tool for the question. For “where does my time go?”, sample. For “how many times was this called?”, trace.

Common mistakes and how to avoid them

• Trusting a profile with too few samples. Under a second of runtime means under a thousand samples at the default rate. Repeat the profile, raise -r, or use a bigger input, and only believe rows that survive.
• Ignoring the error rate. 1.7 percent is fine; 30 to 40 percent means a large share of attempts produced no sample. Cross-check with --blocking.
• Reading the line number as the function start. In these outputs it is the line that was running, so a function can span several rows.
• Mistaking waiting for computing. Wall-clock mode counts sleep and I/O. If a function is high in wall mode and absent in CPU mode, speeding up its code will not help.
• Reading a differential flame graph as absolute time. It compares shares of the run, so fixing one hotspot paints the rest red.
• Optimizing without a safety net. The Step 6 test caught a version that was faster and wrong. Run tests and a full-output comparison after every change.
• Believing the profiler instead of a stopwatch. Use it to decide where to look, then time the change. Percentages in a profile never prove a speedup.
• Mismatched interpreters. Profiler and target must be the same minor version, and exactly the same build if either is a pre-release.

Confirm everything works end to end

After all fixes the program looks like this (the changes from Steps 5 to 7 and 9 are all included):

# report.py
import csv
import re
import sys
import time
from datetime import datetime

SKU_RE = re.compile(r"^[A-Z]{3}-\d{4}$")


def is_valid_sku(sku):
    return SKU_RE.match(sku) is not None


def parse_order(row):
    return {
        "order_id": row["order_id"],
        "placed_at": datetime.fromisoformat(row["placed_at"]),
        "region": row["region"],
        "sku": row["sku"],
        "qty": int(row["qty"]),
        "unit_price": float(row["unit_price"]),
    }


def read_orders(path):
    orders = []
    with open(path, newline="") as f:
        for row in csv.DictReader(f):
            if is_valid_sku(row["sku"]):
                orders.append(parse_order(row))
    return orders


def drop_duplicates(orders):
    seen_ids = set()
    unique = []
    for order in orders:
        if order["order_id"] not in seen_ids:
            seen_ids.add(order["order_id"])
            unique.append(order)
    return unique


def revenue_by_region_and_day(orders):
    totals = {}
    for o in orders:
        key = (o["region"], o["placed_at"].date())
        totals[key] = totals.get(key, 0.0) + o["qty"] * o["unit_price"]
    return totals


def build_report(path):
    orders = drop_duplicates(read_orders(path))
    totals = revenue_by_region_and_day(orders)
    days = sorted({o["placed_at"].date() for o in orders})
    lines = [f"orders={len(orders)}"]
    for region in ("north", "south", "east", "west"):
        by_day = {day: round(totals.get((region, day), 0.0), 2) for day in days}
        best_day = max(by_day, key=by_day.get)
        lines.append(
            f"{region:<6} days={len(by_day)} best={best_day} "
            f"best_revenue={by_day[best_day]:,.2f} total={sum(by_day.values()):,.2f}"
        )
    return "\n".join(lines)


if __name__ == "__main__":
    started = time.perf_counter()
    print(build_report(sys.argv[1]))
    print(f"elapsed {time.perf_counter() - started:.2f}s", file=sys.stderr)

Run the three checks one last time:

python -m pytest -q
python report.py orders.csv > after.txt
python check_same.py baseline.txt after.txt

...                                                                      [100%]
3 passed in 0.04s
elapsed 0.07s
identical

Three tests pass, the elapsed line shows the fast time, and identical confirms the report matches the one the slow original produced. That is the full loop: measure, find the top row, think about why it is slow, change one thing, check that behavior is unchanged, and measure again.

Where to go next

• Explore the options this tutorial skipped. The docs describe --all-threads (sample every thread, not just the main one), --mode gil and --mode exception, --async-aware for stacks across await boundaries, --subprocesses to profile Python child processes, --opcodes for bytecode-level detail, and --live for a real-time view.
• Profile import time as well as run time with our Python 3.15 lazy imports tutorial, which cut a command-line tool’s startup time using the same release.
• Time changes properly with the Python timer class tutorial, and summarize repeated timings with medians and percentiles using the descriptive statistics tutorial.
• When the slow part spans several services, a per-process profiler is not enough. See how to instrument a FastAPI app with OpenTelemetry for distributed traces.
• For context on the release, our earlier piece on Python 3.15’s feature freeze listed the sampling profiler in its checklist, with the advice to try it on representative workloads, which is what you have now done.

Sources

• profiling.sampling, Statistical profiler (Python 3.15 documentation)
• profiling.tracing, Deterministic profiler (Python 3.15 documentation)
• PEP 799, A dedicated profiling package for organizing Python profiling tools
• PEP 790, Python 3.15 Release Schedule