Sampling Profiler: Tachyon (profiling.sampling)

Authors

K19G

grok-bot

Updated

October 31, 2026

Sampling Profiler: Tachyon (profiling.sampling)

Thesis

cProfile answers “how many times was each function called, and for how long?” by hooking every call and return. That precision has a price: the program you measure is no longer the program you run. Python 3.15 ships a second, opposite kind of profiler in the standard library. Tachyon (python -m profiling.sampling, from PEP 799) never runs inside the target. It reads the target’s interpreter stacks from outside the process at a fixed rate and counts what it sees. The program runs at full speed, so the numbers describe the real program. You lose exact call counts in exchange. Use Tachyon first to find where time goes, and use tracing only when you need exact counts.

Version note: every listing in this chapter was run on CPython 3.15.0rc3 (Linux x86-64, installed with uv python install 3.15.0rc3). 3.15.0 final is scheduled for 2026-10-09. Where the rc3 tool differs from the documentation, the chapter says so. The book’s baseline is 3.14, which has no profiling package. On 3.14 only cProfile exists.

Mental model

          your program (unchanged)                    Tachyon (separate process)
 ┌───────────────────────────────────┐        ┌─────────────────────────────────────┐
 │ main() → parse() → LINE.match()   │◄─read──│ every 1 ms (default 1 kHz):         │
 │   frames live in interpreter memory│ memory │   copy the frame chain of each       │
 │   no hooks, no tracing, no pauses │        │   sampled thread, record the stack  │
 └───────────────────────────────────┘        │ at the end: count stacks → estimate │
                                              │   time = samples × interval          │
                                              └─────────────────────────────────────┘
Question profiling.tracing (cProfile) profiling.sampling (Tachyon)
How does it measure? A callback on every call/return, inside the process Reads stacks from another process at a fixed rate
Exact call counts? Yes No. Sample counts only
Overhead on the target Large for call-heavy code (8× below) Not measurable on this box at 1 kHz
Attach to a running process? No Yes: attach PID
What can it tell apart? Python functions Wall vs CPU vs GIL-held vs exception time, threads, asyncio tasks
Good for short scripts (< 1 s)? Yes Not alone: too few samples

Three facts to hold on to:

  • Times are estimates. tottime is samples × interval. A function seen in 1,000 of 3,000 samples at 1 kHz “took” about 1.0 s. Double the run time and you double the precision.
  • Rows are per line, not per function. The pstats table key is file:line(function), and the line is the one executing when the sample was taken. A function with three hot lines shows up as three rows. That is a feature: it tells you which line.
  • Main thread only, unless you ask. By default Tachyon samples only the main thread. Add -a for every thread (see The trap).

Since 3.15 the old names are thin aliases. cProfile still works and is the same code as profiling.tracing. The pure-Python profile module is deprecated and will be removed in 3.17.

Worked examples

Case 1: Find the hotspot in a report job

Save as report.py. It is a small batch job. It builds a log, waits on an “upstream” (a 1-second sleep stands in for a network call), counts paths, and fingerprints the input. One of those steps is written badly.

# report.py
import hashlib
import re
import time

LINE = re.compile(r"(?P<ip>\d+\.\d+\.\d+\.\d+) .* \"(?P<verb>[A-Z]+) (?P<path>\S+)")


def make_log(n):
    return [f"10.0.{i % 256}.{i % 7} - - [08/Oct/2026] \"GET /api/item/{i % 500} HTTP/1.1\" 200"
            for i in range(n)]


def parse(lines):
    hits = {}
    for line in lines:
        m = LINE.match(line)
        path = m.group("path")
        hits[path] = hits.get(path, 0) + 1
    return hits


def slow_top(hits, k):
    # O(n*k): rescans the dict once per slot
    top = []
    remaining = dict(hits)
    for _ in range(k):
        best = max(remaining, key=remaining.get)
        top.append((best, remaining.pop(best)))
    return top


def fingerprint(lines):
    h = hashlib.sha256()
    for _ in range(40):
        h.update("\n".join(lines).encode())
    return h.hexdigest()[:12]


def fetch_upstream():
    time.sleep(1.0)  # stands in for a network call


def main():
    lines = make_log(300_000)
    fetch_upstream()
    hits = parse(lines)
    top = slow_top(hits, 400)
    print("top:", top[0], "fingerprint:", fingerprint(lines))


if __name__ == "__main__":
    main()

Run it under Tachyon. run starts the script as a child process and samples it from the first line. There is no PID to look up.

uv run --python 3.15.0rc3 python -m profiling.sampling run report.py

Output (the default pstats table, sorted by direct samples, top 15):

top: ('/api/item/0', 600) fingerprint: 190018c62bb3
Captured 3213 samples in 3.21 seconds
Sample rate: 1000.00 samples/sec
Error rate: 0.47
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1793/1793      56.1         1.793      56.1         1.793  report.py:36(fingerprint)
      1000/1000      31.3         1.000      31.3         1.000  report.py:41(fetch_upstream)
        171/171       5.3         0.171       5.3         0.171  report.py:17(parse)
        136/136       4.3         0.136       4.3         0.136  report.py:10(make_log)
          42/42       1.3         0.042       1.3         0.042  report.py:18(parse)
          32/32       1.0         0.032       1.0         0.032  report.py:19(parse)
            6/6       0.2         0.006       0.2         0.006  report.py:16(parse)
         5/3194       0.2         0.005      99.9         3.194  report.py:53(<module>)
            4/4       0.1         0.004       0.1         0.004  report.py:11(make_log)
            4/4       0.1         0.004       0.1         0.004  report.py:28(slow_top)
            1/1       0.0         0.001       0.0         0.001  <frozen importlib._bootstrap_external>:1386(FileFinder.find_spec)
            1/1       0.0         0.001       0.0         0.001  <frozen importlib._bootstrap>:549(_call_with_frames_removed)
            1/1       0.0         0.001       0.0         0.001  _parser.py:848(_parse)
            1/1       0.0         0.001       0.0         0.001  report.py:27(slow_top)
            0/1       0.0         0.000       0.0         0.001  <frozen importlib._bootstrap_external>:1244(PathFinder._get_spec)

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, 56.1% direct samples: report.py:(fingerprint)
  1.000 direct/cumulative ratio, 31.3% direct samples: report.py:(fetch_upstream)
  1.000 direct/cumulative ratio, 7.9% direct samples: report.py:(parse)

Functions with Highest Call Frequency (Indirect Calls):
  3189 indirect calls, 99.9% total stack presence: report.py:(<module>)
  1 indirect calls, 0.0% total stack presence: <frozen importlib._bootstrap_external>:(PathFinder._get_spec)

Functions with Highest Call Magnification (Cumulative/Direct):
  638.8x call magnification, 3189 indirect calls from 5 direct: report.py:(<module>)

How to read it:

  • nsamples is direct/cumulative. 1793/1793 means line 36 was on top of the stack in 1,793 samples. 5/3194 for <module> means it was almost never on top but was on the stack the whole time.
  • Line 36 is h.update("\n".join(lines).encode()). More than half of the run is spent there. The table points at the exact line, not just “somewhere in fingerprint”.
  • fetch_upstream is 1,000 samples, exactly the 1.0 s sleep. The default mode is wall-clock, so waiting counts.
  • slow_top is nearly invisible (8 samples). The obvious O(n·k) loop is not the problem with 500 distinct paths. This is why you measure before you rewrite.
  • Error rate is the percentage of sample attempts that failed (a stack read that raced with the interpreter changing it). Under 1% is normal.

The rc3 build prints the Legend even with --no-summary. The documentation says that flag hides both. Later listings drop the legend for space.

Case 2: Wall, CPU, and GIL: three questions, three modes

Wall time says where the job waits as well as where it works. To see where it burns CPU, switch modes. CPU mode keeps only the samples where the thread was on a CPU:

uv run --python 3.15.0rc3 python -m profiling.sampling run --mode=cpu --no-summary -l 6 report.py
top: ('/api/item/0', 600) fingerprint: 190018c62bb3
Captured 2968 samples in 2.97 seconds
Sample rate: 1000.00 samples/sec
Error rate: 0.40
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1707/1707      87.3         1.707      87.3         1.707  report.py:36(fingerprint)
        106/106       5.4         0.106       5.4         0.106  report.py:17(parse)
          84/84       4.3         0.084       4.3         0.084  report.py:10(make_log)
          23/23       1.2         0.023       1.2         0.023  report.py:19(parse)
          19/19       1.0         0.019       1.0         0.019  report.py:18(parse)
         7/1954       0.4         0.007      99.9         1.954  report.py:53(<module>)

fetch_upstream is gone: a sleeping thread is not on a CPU. If a function is high in wall mode and absent in CPU mode, it is waiting. Making its code faster will not help; reducing the wait (concurrency, caching, a faster upstream) will.

The fix for line 36 is to build the joined bytes once instead of 40 times. Save as report_fixed.py. It is report.py with one changed function:

# report_fixed.py (only fingerprint() differs from report.py)
def fingerprint(lines):
    h = hashlib.sha256()
    blob = "\n".join(lines).encode()   # build the bytes once
    for _ in range(40):
        h.update(blob)
    return h.hexdigest()[:12]
cp report.py report_fixed.py   # then edit fingerprint() as above
time uv run --python 3.15.0rc3 python report_fixed.py
top: ('/api/item/0', 600) fingerprint: 190018c62bb3

real    0m1.869s
user    0m0.802s
sys 0m0.068s

The fingerprint is identical and the job went from about 3.1 s to 1.9 s wall time, of which 1.0 s is the sleep. Now compare CPU mode with GIL mode on the fixed version. GIL mode keeps only samples where the thread held the GIL, that is, was running Python bytecode or C code that did not release the lock:

uv run --python 3.15.0rc3 python -m profiling.sampling run --mode=cpu -l 5 --no-summary report_fixed.py
top: ('/api/item/0', 600) fingerprint: 190018c62bb3
Captured 1781 samples in 1.78 seconds
Sample rate: 1000.00 samples/sec
Error rate: 0.67
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        487/487      63.3       487.000      63.3       487.000  report_fixed.py:37(fingerprint)
        120/120      15.6       120.000      15.6       120.000  report_fixed.py:17(parse)
          81/81      10.5        81.000      10.5        81.000  report_fixed.py:10(make_log)
          31/31       4.0        31.000       4.0        31.000  report_fixed.py:35(fingerprint)
          22/22       2.9        22.000       2.9        22.000  report_fixed.py:18(parse)
uv run --python 3.15.0rc3 python -m profiling.sampling run --mode=gil -l 5 --no-summary report_fixed.py
top: ('/api/item/0', 600) fingerprint: 190018c62bb3
Captured 1835 samples in 1.84 seconds
Sample rate: 1000.00 samples/sec
Error rate: 0.65
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        110/110      35.8       110.000      35.8       110.000  report_fixed.py:17(parse)
          85/85      27.7        85.000      27.7        85.000  report_fixed.py:10(make_log)
          46/46      15.0        46.000      15.0        46.000  report_fixed.py:35(fingerprint)
          24/24       7.8        24.000       7.8        24.000  report_fixed.py:19(parse)
          20/20       6.5        20.000       6.5        20.000  report_fixed.py:18(parse)

Line 37 (h.update(blob)) is 63% of CPU time and absent from GIL mode. hashlib releases the GIL while it hashes large buffers, so that CPU time is available to other threads. Line 35 ("\n".join) stays in GIL mode: building a string holds the lock. In a threaded server, that is the line that starves other threads. GIL mode is the profile to read when “more threads made it slower”.

The other mode is --mode=exception. It keeps samples taken while an exception is propagating or an except block is running, which is useful when a parser uses exceptions for control flow.

Case 3: Same data, many views: flame graphs, collapsed stacks, replay

Every format is a flag on the same command. --flamegraph and --heatmap write self-contained HTML; --collapsed writes one line per unique stack for external flame-graph tools; --gecko writes JSON for the Firefox Profiler. Rather than profiling once per format, record once in the compact binary format and replay it:

uv run --python 3.15.0rc3 python -m profiling.sampling run --binary -o baseline.bin report.py
top: ('/api/item/0', 600) fingerprint: 190018c62bb3
Captured 2942 samples in 2.94 seconds
Sample rate: 1000.00 samples/sec
Error rate: 0.44
  Binary Encoding:
    Records:          437
      RLE repeat:     164 (37.5%) [2,649 samples]
      Full stack:     1 (0.2%)
      Suffix match:   0 (0.0%)
      Pop-push:       272 (62.2%)
  Frame Efficiency:
    Frames written:   296
    Frames saved:     23,091 (98.7%)
    Bytes (pre-zstd): 15.1 KB
Binary profile written to baseline.bin (2929 samples)

A three-second profile is 15 KB before compression. That is small enough to attach to a ticket. Replay it into a flame graph and into collapsed stacks:

uv run --python 3.15.0rc3 python -m profiling.sampling replay --flamegraph -o baseline.html baseline.bin
uv run --python 3.15.0rc3 python -m profiling.sampling replay --collapsed -o baseline.collapsed baseline.bin
awk '{print $NF"\t"$0}' baseline.collapsed | sort -nr | cut -f2 | head -3
Flamegraph data: 1 root function, 2928 total samples, 94 unique strings
Flamegraph saved to: baseline.html
Replayed 2929 samples
Collapsed stack output written to baseline.collapsed
Replayed 2929 samples
tid:429263;<frozen runpy>:_run_module_as_main:201;<frozen runpy>:_run_code:87;report.py:<module>:53;report.py:main:49;report.py:fingerprint:36 1665
tid:429263;<frozen runpy>:_run_module_as_main:201;<frozen runpy>:_run_code:87;report.py:<module>:53;report.py:main:46;report.py:fetch_upstream:41 1000
tid:429263;<frozen runpy>:_run_module_as_main:201;<frozen runpy>:_run_code:87;report.py:<module>:53;report.py:main:47;report.py:parse:17 116

Each collapsed line is a full stack from the thread ID down to the executing line, followed by its sample count. The awk sorts by that count, which is the last field. Frames like <frozen runpy> contain spaces, so a plain sort -k2 would pick the wrong column. This text format is what external tools (flamegraph.pl, speedscope) expect, and it is easy to grep and diff in a terminal.

The best view for “did my fix work?” is a differential flame graph. Profile the new code against the saved baseline:

uv run --python 3.15.0rc3 python -m profiling.sampling run --diff-flamegraph baseline.bin -o diff.html report_fixed.py
top: ('/api/item/0', 600) fingerprint: 190018c62bb3
Captured 1839 samples in 1.84 seconds
Sample rate: 1000.00 samples/sec
Error rate: 0.71
Flamegraph data: 1 root function, 1825 total samples, 119 unique strings
Flamegraph saved to: diff.html

Open diff.html in a browser. Frames are drawn at the new widths and coloured by change in direct time: blue for faster, red for slower, purple for frames that are new. Here fingerprint turns blue and nothing turns red. That is the evidence to put in a pull request.

--heatmap is the line-level view. It writes a directory, not a file:

uv run --python 3.15.0rc3 python -m profiling.sampling run --heatmap -o heat report_fixed.py
Heatmap output written to heat/
  - Index: heat/index.html
  - 1 source file analyzed

Case 4: What it costs the program you measure

Save as calls.py. Recursive Fibonacci is the worst case for a tracing profiler: millions of tiny calls, each one triggering the profiler’s hook.

# calls.py
import time


def fib(n):
    return n if n < 2 else fib(n - 1) + fib(n - 2)


start = time.perf_counter()
fib(32)
print(f"fib(32) took {time.perf_counter() - start:.2f}s")

The script times itself, so each line below is the program’s own view of its speed under each profiler:

uv run --python 3.15.0rc3 python calls.py
uv run --python 3.15.0rc3 python -m profiling.sampling run calls.py | head -1
uv run --python 3.15.0rc3 python -m profiling.sampling run -r 20khz calls.py | head -1
uv run --python 3.15.0rc3 python -m profiling.tracing calls.py | head -1

Three runs on an 8-vCPU VM shared with other work:

Run No profiler Tachyon 1 kHz Tachyon 20 kHz profiling.tracing
1 0.44 s 0.37 s 0.51 s 1.76 s
2 0.22 s 0.20 s 0.24 s 1.74 s
3 0.23 s 0.21 s 0.20 s 2.61 s

The sampled runs are within the box’s own noise (run 1 was a noisy moment for everything). The tracing profiler makes this program 8–11× slower. It also distorts the profile: it inflates cheap, frequently called functions far more than slow, rarely called ones. With a sampler the cost lands on the profiler’s own process, not on the target.

Case 5: Profiling a live process (attach and dump)

run covers anything you can start yourself. For a process that is already running, Tachyon has two more subcommands. They use the same OS permission check as pdb -p and sys.remote_exec:

# sample a running service for 30 s, all threads, into a flame graph
python -m profiling.sampling attach -a -d 30 --flamegraph -o live.html PID

# one traceback-style snapshot of every thread ("what is it doing right now?")
python -m profiling.sampling dump -a PID

# a top-like live view (q to quit)
python -m profiling.sampling attach --live PID

These were not run for this chapter. The examples above stick to run, which samples its own child and needs no extra privilege. Things to know before you attach in production:

  • Permissions. On Linux, reading another process’s memory needs root, CAP_SYS_PTRACE, or a Yama ptrace_scope that allows it. Prefer a one-off sudo over loosening ptrace_scope for the whole host.
  • Same interpreter. Profiler and target must be the same major.minor. If either is a pre-release (like the rc3 used here), they must be the exact same version. Free-threaded and default builds cannot profile each other.
  • The right PID. uv run, shell scripts, and process supervisors put a wrapper in front of Python. Attach to the interpreter, not the wrapper:
# server.py
import os
import time

print("python pid", os.getpid(), flush=True)
time.sleep(30)
uv run --python 3.15.0rc3 python server.py &
ps -o pid,ppid,comm --ppid $! -p $!
python pid 462630
    PID    PPID COMMAND
 462624  462604 uv
 462630  462624 python3.15

$! is the uv process (462624). The interpreter is its child (462630), the PID the script printed, and that is the PID to give attach or dump.

  • dump --blocking pauses the target while it reads, for a guaranteed-consistent snapshot. Without it the read races the running program and can, rarely, produce a torn stack.

The trap

The default profile only sees the main thread. Save as pool.py. The real work happens in two worker threads:

# pool.py
from concurrent.futures import ThreadPoolExecutor


def checksum(n):
    total = 0
    for i in range(n):
        total = (total * 31 + i) % 1_000_003
    return total


def main():
    with ThreadPoolExecutor(max_workers=2) as ex:
        results = list(ex.map(checksum, [8_000_000] * 4))
    print("results:", results[:2])


if __name__ == "__main__":
    main()
uv run --python 3.15.0rc3 python -m profiling.sampling run -l 4 --no-summary pool.py
results: [587857, 587857]
Captured 1805 samples in 1.81 seconds
Sample rate: 1000.00 samples/sec
Error rate: 1.61
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1740/1740      98.0         1.740      98.0         1.740  threading.py:363(Condition.wait)
          14/14       0.8         0.014       0.8         0.014  ~:0(<GC>)
            9/9       0.5         0.009       0.5         0.009  <frozen importlib._bootstrap_external>:923(FileLoader.get_data)
            4/4       0.2         0.004       0.2         0.004  <frozen importlib._bootstrap_external>:922(FileLoader.get_data)

98% “in Condition.wait”. That is true, and useless: the main thread is waiting for results. checksum does not appear at all. Add -a:

uv run --python 3.15.0rc3 python -m profiling.sampling run -a -l 4 --no-summary pool.py
results: [587857, 587857]
Captured 2163 samples in 2.16 seconds
Sample rate: 1000.00 samples/sec
Error rate: 1.11
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      3904/3904      61.4         3.904      61.4         3.904  pool.py:8(checksum)
      2090/2090      32.9         2.090      32.9         2.090  threading.py:363(Condition.wait)
        293/293       4.6         0.293       4.6         0.293  pool.py:7(checksum)
          24/24       0.4         0.024       0.4         0.024  threading.py:372(Condition.wait)

Now the hot loop (line 8) leads. Note what changed in the arithmetic: with -a each “sample” captures every thread, so the per-row tottime values add up to thread-seconds (3.9 s of checksum in a 2.2 s run, because two threads ran it). Percentages are shares of all thread samples, not of the wall clock.

Two smaller traps:

  • Very short programs. A 0.2 s script yields about 200 samples at 1 kHz. Run it in a loop, raise the rate (-r 10khz), or use profiling.tracing for the exact counts.
  • --async-aware is its own world. It rebuilds stacks along await chains and cannot be combined with -a, --native, --no-gc, or the cpu/gil modes.

The boring rule

  • Start every performance question with python -m profiling.sampling run --mode=wall. Switch to --mode=cpu once you know the time is computation, and to --mode=gil when threads are involved.
  • Always pass -a for programs that use threads or thread pools. Read -a totals as thread-seconds.
  • Record once (--binary -o run.bin), then replay into whatever view you need. Keep the baseline .bin and prove fixes with --diff-flamegraph.
  • Use profiling.tracing (cProfile) only when you need exact call counts, and never trust its absolute times for call-heavy code.
  • In production: attach -d 30 with a short duration, a one-off sudo for permission, the interpreter’s PID (not a wrapper’s), and the same Python version as the target.

Try this

  1. Profile report.py at -r 100hz, 1khz, and 20khz. How many samples does each collect, and how much does the fingerprint percentage move between runs at each rate?
  2. Run pool.py with --mode=gil -a. Each worker holds the GIL only part of the time. Then run pool.py on a free-threaded 3.15 build (uv python install 3.15.0rc3+freethreaded) and compare the wall time.
  3. Add a try: int(x) except ValueError: pass loop over mostly non-numeric strings to report.py and find it with --mode=exception.
  4. Generate --gecko -o report.json and load it into the Firefox Profiler. Find the GIL and CPU markers on the timeline.
  5. Start report.py with a longer sleep, find the interpreter PID behind uv run, and run dump -a PID (as yourself, then with sudo if your system refuses). Compare the snapshot with the run profile.

Sources