# Benchmarks — `mgf-common bench`

This file tracks the microbench numbers for the load-bearing
primitives across releases. Re-run `mgf-common bench` on every
release; record the numbers here so regressions are visible.

## How to read this

Each row is "ns per call" — the average time one call takes,
measured over the iteration count shown. Lower = faster.

The numbers are captured on the maintainer's development laptop
(Linux, x86_64, Python 3.12). Absolute numbers vary by hardware;
**relative changes between releases are the signal** — a 2× jump
between and means a regression we have to investigate.

CI hardware is slower; expect raw ns/call to be ~2-3× the laptop
numbers in the CI environment. CI's job is to detect changes >50%
release-over-release on the same hardware.

## Reproducing

```bash
$ mgf-common bench # full-budget run, ~2 seconds
$ mgf-common bench --quick # quick-pass, ~0.5 seconds
$ mgf-common bench --json # machine-readable output
```

## Numbers (initial bench)

### 2026-04-30

Hardware: laptop, Linux 6.17, Python 3.12.3.

| Operation | ns/call | Iterations |
|---|---:|---:|
| `current_context()` | 161 | 1 000 000 |
| `bootstrap()` cold | 3 069 877 | 1 |
| `bootstrap()` warm | 822 512 | 1 000 |
| `operation_span()` open+close | 3 841 | 100 000 |
| log call (sync, JSON) | 13 898 | 10 000 |
| log call (async, JSON) | 6 236 | 10 000 |
| redaction pass (10-key dict) | 4 872 | 10 000 |

**Headline numbers:**

- `current_context()` — **160 ns**. The contextvar lookup runs on
  every log call's identity-resolution path; it MUST stay sub-µs.
- `bootstrap()` cold — **3 ms**. The full lifecycle wiring
  (logging, OTel, crash hooks). Acceptable for a one-shot startup
  cost; not on a hot path.
- `bootstrap()` warm — **820 µs**. Re-entry calls
  `prior.shutdown()` then re-wires; ~3× cheaper than cold
  because OTel imports are cached. The audit-warning emission
  also adds latency we measure here.
- `operation_span()` open+close — **3.8 µs**. Full OTel span
  alloc + status + exit. With OTel disabled the cost is much
  lower (no-op span); doesn't disambiguate, but a future
  bench may.
- log call (sync, JSON) — **14 µs**. JSON formatter + redaction +
  StreamHandler.write. The redaction pass alone is **5 µs**
  (next row); JSON encode + write account for the remaining 9 µs.
- log call (async, JSON) — **6 µs**. Just the queue.put_nowait;
  the formatter + write run off-CPU on the drain thread. **2.2×
  faster** than the sync path on the calling thread, which is
  what makes async logging worth shipping.
- redaction pass — **4.9 µs**. 10-key dict, default redactor.
  Most of this is the regex pass over string values.

**Targets going forward:**

- `current_context()` — must stay below 1 µs (currently 160 ns;
  10× headroom). Regression triggers a bench-revert.
- `operation_span()` — must stay below 10 µs. The OTel SDK is
  the long-pole; if it grows beyond that, switch to lazy span
  allocation.
- log call (async) — must stay below 10 µs. If the queue
  contention becomes visible (e.g., if we add per-record
  metadata processing on the calling thread), drop the work to
  the drain thread.
- bench walltime — must stay below 5 seconds. The plan's contract;
  it's the gate that lets us run this on every release without
  CI cost concerns.

## Methodology notes

- **Warmup:** every measurement runs `min(100, iterations)` warmup
  calls before the timed loop starts — Python's import-cache and
  function-attribute-resolution effects are amortized away.
- **Iteration counts** scale with the bench mode: `--quick` runs
  20% of the iterations of the full mode. Quick mode is for
  developer iteration; full mode is for release recording.
- **Walltime** includes ALL benchmarks (warmup + measurement +
  the row's own setup, e.g., engine construction for the log
  benches). Total < 5 seconds is the contract.
- **Audit logs are silenced** during the bench because warm
  bootstraps emit them (one per re-entry); without silencing,
  they'd swamp the bench output and slow the calling thread.
- **State pollution:** the bench leaves a process-global
  `AppContext` (`bootstrap()` is genuinely called); when run
  inside the test suite, an autouse fixture cleans it up between
  cases. When run as the CLI, the process exits and the OS
  cleans up.

## Regression policy

1. **Within-release** (CI on a PR): a >50% slowdown in any row
   on the same hardware fails the PR. The author either justifies
   the change (new feature on the hot path) or fixes it.
2. **Release-over-release**: if any row regresses by >25%, the
   release notes call it out explicitly. A regression > 50%
   without a justifying change is a release blocker.
3. **Hardware drift**: if maintainer hardware changes (laptop
   replacement, CI runner upgrade), record a new "calibration"
   row at the same release and use it as the new baseline. Don't
   compare across hardware silently.
