timeit / time.perf_counter — microbenchmarks done right

«Сколько занимает этот код?» — простой вопрос, но наивный ответ (t0 = time.time(); fn(); t1 = time.time(); print(t1-t0)) даёт систематически неправильные числа. Microbenchmarking — отдельная дисциплина: cold cache vs warm cache, GC pauses, JIT warmup (там, где есть JIT), evaluation rules, GIL contention. CPython даёт два инструмента: time.perf_counter() (точный clock) и timeit (правильный harness вокруг него).

В этом уроке:

1. time.perf_counter() vs time.process_time() — wall-clock vs CPU time.
2. timeit.timeit / timeit.repeat — number=N, repeat=R, и min trick.
3. Почему one-shot timing врёт — cold cache, GC, JIT warmup.
4. GIL implications — почему single-threaded micro benchmark не страдает от GIL contention.
5. Pyodide WASM caveat (Pitfall 38) — event-loop interleaving делает timing noisy.
6. Cross-link M02 урок 01 — amortized O(1) list.append подтверждаем через timeit.
7. Run-on-Your-Machine #1 — host timing baseline.

time.perf_counter() vs time.process_time()

Stdlib time модуль предоставляет несколько таймеров — все возвращают float секунды, но измеряют разные вещи:

Production rule:

import time

t0 = time.perf_counter()         # высокоточный wall-clock
# ... код ...
elapsed = time.perf_counter() - t0
print(f'{elapsed*1000:.3f} ms')

time.time() для benchmarks — anti-pattern (NTP может корректировать назад → отрицательный elapsed). Production-инструменты Spark UI, Prometheus, OpenTelemetry также используют monotonic clocks — wall-clock с возможностью отката не годится для измерений (cross-course → Spark 04/01 shuffle-optimization timing analysis).

time.process_time() исключает blocking I/O (socket.recv, disk.read, time.sleep) — полезно когда хочется отделить «CPU work» от «waiting». Для большинства microbenchmarks perf_counter правильный default.

Cite docs.python.org/3/library/time.html — все 4 timer functions.

timeit.timeit / timeit.repeat — number, repeat, и min trick

timeit — harness вокруг perf_counter, делающий три вещи правильно:

1. Disables GC (gc.disable() на время измерения — GC pauses не загрязняют numbers).
2. Best-of-N выбор — repeat() запускает выборку R раз; берётся min, не mean.
3. Auto-loop — number=N вызывает выражение N раз внутри одного timer call → амортизирует overhead perf_counter самого.

API:

import timeit

# Single timing — number=N inner iterations in 1 timer call
t = timeit.timeit('expr', number=10000)
# t — total time для всех 10000 calls; per-call = t / 10000

# Multi-run — repeat=R outer trials
trials = timeit.repeat('expr', number=10000, repeat=5)
# trials — list of 5 floats (каждый = total time для 10000 calls)

# Production rule — always min, not mean
best = min(trials)
per_call = best / 10000

Почему min, а не mean?

• GC может interrupt один из 5 trials — этот trial будет outlier. Mean его подтянет вверх. Min его игнорирует.
• Cold cache affects первый trial. Min обычно — warm-cache result (что мы и хотим знать).
• Page faults / context switches случайно случаются — min фильтрует их.

Cite docs.python.org/3/library/timeit.html — Timer.repeat() documentation explicitly recommends min.

Recipe — typical microbenchmark:

import timeit

# How fast is dict.get vs dict[]?
setup = "d = {'k': 1}"
t_get = min(timeit.repeat("d.get('k')", setup=setup, number=1_000_000, repeat=5))
t_idx = min(timeit.repeat("d['k']", setup=setup, number=1_000_000, repeat=5))
print(f'get: {t_get*1e9/1e6:.1f} ns/call')
print(f'idx: {t_idx*1e9/1e6:.1f} ns/call')

number подбирается так чтобы total time ≥ 0.2 sec (рекомендация docs) — иначе perf_counter resolution становится noticeable. Auto-tune: Timer.autorange() подберёт N.

Почему one-shot timing врёт

Простейший наивный benchmark:

# WRONG — one-shot timing
import time
t0 = time.perf_counter()
result = expensive_func()
print(time.perf_counter() - t0)

Что систематически неправильно:

1. Cold cache — первый call холодный CPU L1/L2 cache + холодный TLB; subsequent calls могут быть в 2-10x быстрее. One-shot мерит cold case.
2. GC может triggered в самом середине вызова — 50ms GC pause в 100ms benchmark = 50% noise.
3. Page fault — если функция первый раз trigger’ит memory mapping, page fault adds milliseconds (cross-link M02 урок 02 PyListObject memory baseline).
4. JIT warmup — в CPython нет JIT, но в PyPy / specialized adaptive interpreter (PEP 659, Python 3.11+) первый run собирает type-feedback, subsequent runs faster.
5. Process scheduling — OS может switch контекст в любой момент; single measurement не отделяет «время функции» от «время ожидания CPU».

Поэтому timeit берёт repeat=5 × number=10000 × min — это filter для всех 5 эффектов одновременно.

Cross-course → Spark 04/01 shuffle-optimization — distributed Spark UI показывает task duration percentiles (p50/p95/p99) precisely потому что individual task times noisy.

GIL implications в timing

Single-threaded microbenchmark (то, что timeit делает по умолчанию) НЕ страдает от GIL contention — есть только один Python thread, GIL никогда не contended.

GIL начинает влиять на timing когда:

1. Multiple threads competing — threading.Thread-based parallel work mер’ится через wall-clock; GIL serialization добавляет overhead.
2. C-extension calls releasing GIL — time.sleep() releases GIL; пока main thread sleep, другие threads могут run.
3. gc.collect() in middle — GC может interrupt любой thread, добавляет latency.

timeit.timeit('expr', number=N, globals=globals()) — globals= parameter позволяет access к module variables в expression string. Без globals= — expr runs в чистом namespace.

Production rule — для multi-threaded benchmarks timeit не подходит; используйте concurrent.futures.ThreadPoolExecutor + time.perf_counter() manual harness, или pytest-benchmark (НЕ Pyodide-доступен).

Cross-course → Урок 06 (GIL + threading + multiprocessing) — там detailed mental model.

Pyodide WASM caveat (Pitfall 38)

Pyodide запускает Python в browser через WebAssembly. Browser event-loop interleaves Python execution с DOM events, network I/O, GC браузера. Это значит:

1. time.perf_counter() в Pyodide имеет precision как performance.now() JS API — обычно 1ms, иногда reduced (Spectre mitigations).
2. Browser может pause Python execution для render tasks — несколько ms gaps в середине benchmark.
3. GC браузера не контролируется Python gc.disable() — JS GC может pause всё.

Для Phase 69 это означает: inline browser timing assertions в challenges — unreliable. Therefore challenges в M12 (Patterns 2 + 4) — structural / stdlib parsing, не timing-dependent.

Real timing benchmarks → Run-on-Your-Machine. Browser challenges → text parsing (cProfile pre-captured stats), bytecode introspection (dis), schema validation — детерминированные результаты независимые от timing.

Cite pyodide.org/en/stable/usage/wasm-constraints.html.

Cross-link M02 урок 01 — amortized O(1) list.append подтверждаем через timeit

В М02 урок 01 (PyListObject, amortized analysis) мы вывели: list.append — amortized O(1) благодаря geometric reallocation (capacity *= 1.125 при overflow). Это theoretical результат. timeit даёт empirical подтверждение:

import timeit

# Append 10_000 раз; timing ~ 10_000 amortized О(1) calls
def append_n(n):
    lst = []
    for _ in range(n):
        lst.append(0)
    return lst

t10k = min(timeit.repeat(lambda: append_n(10_000), number=100, repeat=5))
t100k = min(timeit.repeat(lambda: append_n(100_000), number=100, repeat=5))
print(f'10k:  {t10k*1000:.2f} ms per run')
print(f'100k: {t100k*1000:.2f} ms per run')
print(f'ratio: {t100k/t10k:.2f}x (expected ~10x for O(n))')

Если ratio ≈ 10x → amortized O(1) append подтверждён (linear scaling в N appends → per-append constant). Если бы append был O(n) — ratio был бы 100x. Это timeit как verification tool для теоретических big-O claims из M02.

Pragmatic-DEEP принцип: timeit — не только performance tool, но и debugger for big-O assumptions. Если новая структура данных claim’ит O(1) operation, timing на N=10k vs N=100k показывает реальную сложность.

Cross-course → DataFusion 02/07 memory-management — same principle (Rust’s Vec::push тоже amortized O(1) с geometric reallocation; profiling confirms timing).

Run-on-Your-Machine #1 — host timing baseline

python --version  # >=3.11 рекомендуется

import timeit
from collections import deque

setup_list = "lst = []"
setup_deque = "from collections import deque; dq = deque()"

t_list = min(timeit.repeat("lst.append(0)", setup=setup_list, number=1_000_000, repeat=5))
t_deque = min(timeit.repeat("dq.append(0)", setup=setup_deque, number=1_000_000, repeat=5))

print(f'list.append:  {t_list*1e9/1e6:.1f} ns/call')
print(f'deque.append: {t_deque*1e9/1e6:.1f} ns/call')
print(f'list / deque ratio: {t_list/t_deque:.2f}x')

python bench_append.py

list.append:  47.3 ns/call
deque.append: 52.8 ns/call
list / deque ratio: 0.90x

Что в следующем уроке

Урок 02 — cProfile + pstats — function-level profiling, deterministic vs sampling, observer effect, и Pattern 2 challenge py-m12-02-code-1 (parse pre-captured pstats text output via regex — pure stdlib).

Pragmatic-DEEP принцип: timeit отвечает «сколько занимает X». cProfile отвечает «какая часть программы — bottleneck». Это разные tools для разных вопросов: micro vs macro profiling.

Cite docs.python.org/3/library/timeit.html + docs.python.org/3/library/time.html + PEP 659 — specialized adaptive interpreter.