Skip to content

fix(session): stop --phase-profile paying for the activation-memory planner - #1226

Merged
justinchuby merged 1 commit into
mainfrom
squad/leon-p15-profiler
Aug 18, 2026
Merged

justinchuby merged 1 commit into
mainfrom
squad/leon-p15-profiler

Conversation

@justinchuby

@justinchuby justinchuby commented Aug 18, 2026 •

Copy link
Copy Markdown
Owner

The defect

The executor ran its activation-memory planner whenever phase profiling was on:

let measure_activation_plan = !nested
    && mode == RunMode::Eager
    && stage2.plan.is_none()
    && activation_memory_planning_enabled();   // == phase_profile::enabled()

The planner rebuilds the view map and re-plans every activation, on every run -
work the shipped runtime never does. So --phase-profile perturbed the run it was
measuring, and then reported its own cost back as a phase of that run
(run_scoped.activation_memory_plan) that no unprofiled run ever pays.

Magnitude - corrected after review

The planner's own span reads 1.9-6.0 us per run. Removing it lowers native_min
on sm_decode_h32_kv4096 from 0.065 ms to 0.063 ms - median of 15 interleaved
repetitions, 300 runs each, --native-threads 1 --ort-intra-threads 1, both arms in
one loop. About 3%, in line with the span. 13 of 15 repetitions favour the fixed
arm.

Two claims from the first draft of this PR are withdrawn. It claimed a 35%
inflation (0.065 -> 0.088 ms, ratio 1.023 -> 1.080) and that the planner also
polluted the adjacent exec_kernel.compute figure (84.5 vs 60.3 us/call). The
reviewer could not reproduce either. A properly interleaved re-measurement showed
both were artifacts of a bimodal, contended host and of comparing arms across
separate invocation windows: the 0.065/0.088 split appears in both arms, and
exec_kernel.compute swings 75-168 us/call regardless of the planner. My original
numbers came from non-interleaved runs, which is exactly the discipline this repo's
own benchmark notes insist on and which I did not follow.

The change stands on the smaller, reproducible effect and on the profiler no longer
reporting a phantom phase.

The fix

The planner gets its own gate, separate from the profiler's:

  • --phase-profile calls enable_exec_phase_profile_for_process, which now drives
    the profiler only.
  • NXRT_EXEC_PHASE_PROFILE=1 in the environment still enables both, so the CLI
    memory report (interactive.rs -> activation_memory_plan_stats) keeps working
    through the path it already used.
  • NXRT_ACTIVATION_MEMORY_PLAN=1, or enable_activation_memory_plan_for_process(),
    opts into planning without profiling.

Reading the environment directly, rather than calling enabled(), is what separates
the programmatic enable from the environment one.

Deliberate behaviour change: the CUDA step profiler
(native_decode/cuda.rs) called enable_exec_phase_profile_for_process and so
switched the planner on as a side effect - taxing the very decode steps it exists to
time. That coupling is not restored, and the reason is now a comment at the call
site. A CUDA-step-profiling user who was relying on the incidental activation-plan
numbers must now ask for them explicitly. Raised by review as finding 1.

The first regression test was vacuous

The gate was hardcoded true under cfg(test):

fn activation_memory_planning_enabled() -> bool {
    #[cfg(test)] { true }
    #[cfg(not(test))] { phase_profile::enabled() }
}

so the production wiring was the one line no unit test could reach. My first test
asserted on the phase_profile module functions, passed, and still passed when I
re-coupled the planner to phase profiling in run.rs. It pinned the parts, not the
wiring.

The cfg(test) override is gone. Tests and production share one gate, the two tests
that need planning ask for it through an RAII guard that clears it again on drop, and
re-coupling the wiring now fails both of them (verified).

Review findings addressed

  1. CUDA step profiler behaviour change - documented at the call site; the
    "works exactly as before" wording is corrected to "the environment path works as
    before".
  2. Planner tests leaked PLAN_STATE = on - replaced the bare
    force_activation_plan_enabled(true) with an RAII guard that takes the globals
    lock and clears the gate on drop, including on panic.
  3. cost -> costs typo - fixed.
  4. activation_memory_plan_stats doc implied native+executed was sufficient -
    now states the gate is required.

Tests

  • cargo test -p onnx-runtime-session --lib - 181 passed
  • cargo test -p onnx-genai-engine --lib - 405 passed
  • cargo test -p onnx-runtime-ep-cpu --lib - 1340 passed
  • cargo test -p onnx-runtime-ep-cpu-plugin --test plugin_ort_e2e - 54 passed
  • cargo fmt --all --check, cargo clippy clean

No ORT fallback, no defer, no runtime MLAS, no scheduler changes.

…lanner

The executor ran its activation-memory planner whenever phase profiling was
on. The planner rebuilds the view map and re-plans every activation on every
run - work the shipped runtime never does. So the profiler perturbed the run
it was measuring and then reported its own cost back as a phase of that run,
`run_scoped.activation_memory_plan`, which no unprofiled run ever pays.

The planner now has its own gate. --phase-profile calls
enable_exec_phase_profile_for_process, which drives the profiler only;
NXRT_EXEC_PHASE_PROFILE=1 in the environment still enables both, so the CLI
memory report keeps its stats via the path it already used, and
NXRT_ACTIVATION_MEMORY_PLAN=1 opts in without profiling.

Magnitude, measured honestly. The planner's own span reads 1.9-6.0 us per run.
Removing it lowers native_min on sm_decode_h32_kv4096 from 0.065 ms to
0.063 ms, median of 15 interleaved repetitions, 300 runs each, single thread -
about 3%, in line with the span.

An earlier draft of this message claimed 35% and claimed the planner also
polluted the adjacent exec_kernel.compute figure. Review could not reproduce
either, and a properly interleaved re-measurement showed both were artifacts:
this host is bimodal under contention, the 0.065/0.088 ms split appears in
both arms, and exec_kernel.compute swings 75-168 us/call regardless of the
planner. Both claims are withdrawn. The change stands on the smaller effect
and on not reporting a phantom phase.

The CUDA step profiler used to switch the planner on as a side effect of
enabling phase accounting, so it taxed the very decode steps it exists to
time. It no longer does; that coupling was accidental and is not restored.

The first attempt at a regression test was vacuous. The gate was hardcoded
true under cfg(test), so the production wiring was the one line no unit test
could reach, and re-coupling the planner to phase profiling still passed. That
override is gone: tests and production now share one gate, the two tests that
need planning ask for it explicitly through an RAII guard that clears it again
on drop, and re-coupling the wiring now fails both of them. The process-global
gates are plain atomics with no per-test isolation, so every test that writes
them takes a shared lock.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby
justinchuby force-pushed the squad/leon-p15-profiler branch from 075d8ea to 25a9c10 Compare August 18, 2026 06:49
@justinchuby
justinchuby marked this pull request as ready for review August 18, 2026 06:49
@justinchuby
justinchuby merged commit a1b9b0e into main Aug 18, 2026
5 of 15 checks passed
@justinchuby
justinchuby deleted the squad/leon-p15-profiler branch August 18, 2026 06:50
justinchuby added a commit that referenced this pull request Aug 18, 2026
…ments (#1230)

Records Phase 10 in the CPU-EP evidence document.

**30.1-30.2** — the profiler defect fixed in #1226. The
activation-memory planner ran
on every run whenever phase profiling was on, so `--phase-profile`
perturbed the run
it was measuring and reported its own cost back as a phase of that run.
Real
magnitude: the planner's own span reads 1.9-6.0 us/run, and removing it
lowers
`native_min` on `sm_decode_h32_kv4096` from 0.065 ms to 0.063 ms (median
of 15
interleaved repetitions, 300 runs each, 13/15 favouring the fixed arm) —
about 3%.

**Withdrawn:** the 35% figure (0.065 -> 0.088 ms, ratio 1.023 -> 1.080)
and the claim
that the planner polluted the adjacent `exec_kernel.compute`
measurement. Review could
not reproduce either; interleaved re-measurement showed the 0.065/0.088
split appears
in *both* arms and `exec_kernel.compute` swings 75-168 us/call
regardless.

**30.3** — the methodology lesson, which is the point of the section.
The withdrawn
numbers came from running arm A three times then arm B three times and
reading the
mean, on a host that drifts between the halves. Now the standing rule
for this
document: interleave at the innermost level, prefer `native_min` to the
mean on small
graphs, and distrust an effect an order of magnitude larger than the
mechanism it is
attributed to — the planner's span said 2-6 us while the wall clock
claimed 23 us, and
that inconsistency was visible in my own output before review saw it.

**30.4** — the fourth vacuous test found in this effort, and the one
that is actually
interesting: it passed, and still passed when the behaviour it covered
was deliberately
reverted, because the production wiring sat under `#[cfg(test)]` where
no unit test
could reach it.

Also notes that section 21's boundary instrument, and every per-phase
attribution
derived from it, were taken under the coupled gate and should be
re-read.

Documentation only. No code changes.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@github-actions

Copy link
Copy Markdown

🔴 Benchmark Regression Detected

Comparison of criterion micro-benchmarks: PR head vs merge-base, measured on the same runner in the same job (base first → PR second).

ℹ️ Absolute times are informational only — they vary with runner load. The % change column is the reliable signal because both sides ran under identical conditions.

Status Scenario Base PR Change
🔴 block_quantized_matmul_cached_dense/mxfp4_cached_dense_repeated_call/1x1024x1024 46.08 µs 71.66 µs +55.5%
⚠️ gather/large_f16_threads=1-internal/131072 12.20 µs 15.57 µs +27.5%
⚠️ matmul/small_generic_f16_threads=1/1x256x256 29.52 µs 34.50 µs +16.9%
✅ qwen3_sampling_processors/top_k_partial_selection 142.13 µs 162.00 µs +14.0%
✅ gather/small_f32_threads=1-internal/4096 784.7 ns 868.1 ns +10.6%
✅ reduce_mean/small_f32_threads=1-internal/4096 15.77 µs 17.03 µs +8.0%
✅ add/large_f16_threads=1-internal/4194304 1.82 ms 1.95 ms +6.7%
✅ matmul/small_generic_f32_threads=8/1x256x256 36.72 µs 39.12 µs +6.5%
✅ qwen3_sampling_processors/top_p_full_sort_after_top_k_baseline 3.63 ms 3.82 ms +5.1%
✅ matmul/small_generic_f32_threads=1/1x256x256 36.20 µs 37.92 µs +4.8%
✅ add/large_f32_threads=1-internal/4194304 809.31 µs 842.54 µs +4.1%
✅ gather/medium_bf16_threads=1-internal/32768 2.44 µs 2.50 µs +2.5%
✅ add/large_bf16_threads=1-internal/4194304 1.85 ms 1.86 ms +0.2%
✅ gather/medium_f32_threads=1-internal/32768 4.00 µs 3.99 µs -0.3%
✅ reduce_mean/medium_f32_threads=1-internal/65536 263.26 µs 262.30 µs -0.4%
✅ logit_processing/seven_processor_chain_per_step 335.77 µs 334.33 µs -0.4%
✅ qwen3_sampling_processors/top_k_top_p_full_sort_baseline 6.45 ms 6.41 ms -0.6%
✅ grammar_masking/llguidance_compute_mask/32 84.30 µs 83.58 µs -0.9%
✅ kv_cache/alloc_dealloc_pages 40.20 µs 39.79 µs -1.0%
✅ gather/small_f16_threads=1-internal/4096 539.8 ns 532.6 ns -1.3%
✅ qwen3_sampling_processors/top_k_top_p_fast 686.06 µs 673.82 µs -1.8%
✅ matmul/medium_generic_f32_threads=1/32x512x512 2.21 ms 2.17 ms -1.9%
✅ matmul/large_generic_f32_threads=1/32x1024x1024 9.36 ms 9.12 ms -2.6%
✅ qwen3_sampling_processors/top_k_full_sort_baseline 2.21 ms 2.15 ms -2.8%
✅ qwen3_sampling_processors/top_p_fast_after_top_k 561.00 µs 544.75 µs -2.9%
✅ gather/medium_f16_threads=1-internal/32768 2.48 µs 2.40 µs -3.2%
✅ block_quantized_moe_cached_dense/mxfp4_cached_dense_expert_repeated_call/rows=1,H=256,I=256,E=4,top_k=1 171.61 µs 165.96 µs -3.3%
✅ matmul/large_generic_f32_threads=8/32x1024x1024 4.08 ms 3.94 ms -3.4%
✅ matmul/medium_generic_bf16_threads=1/32x512x512 521.97 µs 502.89 µs -3.7%
✅ reduce_mean/large_f32_threads=1-internal/262144 1.19 ms 1.13 ms -4.3%
✅ block_quantized_matmul_cached_dense/mxfp4_uncached_dequant_each_call/1x1024x1024 615.59 µs 588.99 µs -4.3%
✅ matmul/large_generic_bf16_threads=8/32x1024x1024 1.36 ms 1.30 ms -4.4%
✅ matmul/medium_generic_f16_threads=1/32x512x512 29.35 µs 27.87 µs -5.0%
✅ matmul/large_generic_bf16_threads=1/32x1024x1024 2.04 ms 1.93 ms -5.2%
✅ matmul/large_generic_f16_threads=1/32x1024x1024 76.90 µs 72.92 µs -5.2%
✅ matmul/medium_generic_f32_threads=8/32x512x512 964.43 µs 911.70 µs -5.5%
✅ matmul/small_generic_bf16_threads=8/1x256x256 30.85 µs 29.16 µs -5.5%
✅ matmul/medium_generic_bf16_threads=8/32x512x512 396.37 µs 363.84 µs -8.2%
✅ matmul/medium_generic_f16_threads=8/32x512x512 30.62 µs 27.95 µs -8.7%
✅ sampling_latency/top_p_per_token 389.46 µs 354.01 µs -9.1%
✅ add/medium_f16_threads=1-internal/262144 128.14 µs 115.29 µs -10.0%
✅ matmul/small_generic_f16_threads=8/1x256x256 32.13 µs 28.73 µs -10.6%
✅ gather/small_bf16_threads=1-internal/4096 579.2 ns 516.7 ns -10.8%
✅ add/small_f16_threads=1-internal/1024 543.7 ns 484.9 ns -10.8%
✅ add/small_bf16_threads=1-internal/1024 602.2 ns 535.7 ns -11.0%
✅ add/medium_f32_threads=1-internal/262144 30.04 µs 26.53 µs -11.7%
✅ sampling_latency/min_p_per_token 219.54 µs 193.34 µs -11.9%
✅ matmul/small_generic_bf16_threads=1/1x256x256 35.07 µs 30.54 µs -12.9%
✅ tokenization/encode_tokens_per_second 416.00 µs 361.55 µs -13.1%
✅ gather/large_bf16_threads=1-internal/131072 14.32 µs 12.42 µs -13.2%
✅ add/small_f32_threads=1-internal/1024 279.0 ns 239.9 ns -14.0%
✅ add/medium_bf16_threads=1-internal/262144 142.39 µs 122.39 µs -14.0%
🟢 block_quantized_matmul_cached_dense/mxfp4_preexpanded_dense_oncelock_like_proxy/1x1024x1024 51.66 µs 43.45 µs -15.9%
🟢 sampling_latency/top_k_per_token 57.84 µs 48.53 µs -16.1%
🟢 sampling_latency/greedy_per_token 3.65 µs 3.05 µs -16.6%
🟢 tokenization/decode_tokens_per_second 7.02 ms 5.72 ms -18.5%
🟢 gather/large_f32_threads=1-internal/131072 30.80 µs 24.24 µs -21.3%
🟢 matmul/large_generic_f16_threads=8/32x1024x1024 104.48 µs 79.60 µs -23.8%
🟢 block_quantized_moe_cached_dense/mxfp4_uncached_expert_dequant_each_call/rows=1,H=256,I=256,E=4,top_k=1 686.86 µs 504.48 µs -26.6%

Visual flags: ⚠️ ≥ 15% slower, 🔴 ≥ 30% slower — calibrated against measured runner noise (~27% worst-case on multi-threaded matmul)

Host info
CPU: Apple M1 (Virtual)
Cores: 3
OS: Darwin 25.5.0 arm64
Rust: rustc 1.97.1 (8bab26f4f 2026-07-14)
Load avg: { 4.95 3.96 6.47 }
What this cannot catch
  • Regressions in code paths not covered by these benchmarks (e.g., end-to-end decode with a real model)
  • Sub-threshold regressions that compound over multiple PRs
  • Performance changes that only manifest under GPU execution
  • Latency changes in the ORT integration path (these benchmarks exercise the native Rust kernels)

justinchuby added a commit that referenced this pull request Aug 18, 2026
## What

`main` at 4d231ea fails two blocking CI steps on current stable
(rustc/rustfmt 1.9.0, 1.97.1):

```
$ cargo fmt --all -- --check
Diff in crates/onnx-runtime-ep-cuda/src/provider.rs
Diff in crates/onnx-runtime-memory-api/src/allocator.rs
Diff in crates/onnx-runtime-memory-api/src/capability.rs

$ cargo clippy --locked --all-targets -p onnx-runtime-session -- -D warnings
error: field `0` is never read
   --> crates/onnx-runtime-session/src/executor/mod.rs:175:45
```

Both landed while the runner queue was saturated (71 queued / 1 in
progress at the time of writing, nothing completed on `main` since
08:18Z), so no PR has seen a red check yet. Every open PR in the repo
currently inherits both failures.

## Why these fixes

**rustfmt** — mechanical normalisation, no semantic change.

**`ActivationPlanForTest`** (from #1226) is a tuple struct whose single
field is the `globals_lock()` `MutexGuard`. `dead_code` does not model
"this field's value is its `Drop`", so it fires. The guard must stay:
releasing it early is exactly the leaked-planner-gate race the struct
was added to prevent. So the lint is silenced with a comment explaining
the RAII intent, rather than the field removed.

## Verification

| check | result |
| --- | --- |
| `cargo fmt --all -- --check` | clean |
| `cargo clippy --locked --all-targets -p onnx-runtime-session -- -D
warnings` | clean |
| `cargo test --locked -p onnx-runtime-session --lib` | 181 passed, 0
failed |

Found while trying to land the CPU task-runtime stack (#1201 → #1202 →
#1207 → #1232 → #1238); this is unrelated to that work and is
deliberately kept out of it so it can go in on its own.

Working as sebastian (Performance Engineer)

---------

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby added a commit that referenced this pull request Aug 18, 2026
…-ORT headline) (#1259)

## What

Records the correction of record for **#1218** (erf's Estrin-scheme
reassociation), appended as **§32** to the CPU-EP-vs-ORT ledger — the
same document and style where the #1226 (§30.2) and #1230 withdrawals
live.

#1218 landed as *"1.66x -> 1.36x vs ORT"* (~17.7% kernel-time
reduction). On the review host that ratio is **unreproducible** — there
is no pinned ORT reference build here, and the original number came from
different hardware — so it is **withdrawn**. Stated plainly: it was
**neither reproduced nor refuted**, because it was measured against a
reference we do not run.

## What the doc now records

- **The withdrawal**, with the reason (no ORT arm on this box), and a
note that the overstated figure reached **no benchmark table, README, or
source comment** — only the (unrewritable) squash-commit subject.
- **The measured number:** ORT-independent same-binary A/B on
`erf_avx2`, single-thread, min-of-200 × 9 rounds, 1M elements, on
**Intel Core i7-13800H** — Horner 0.6346 ms → Estrin 0.6042 ms,
non-overlapping ranges → **~5.0% (1.05x)**. Real, but a fraction of the
implied ~17.7%.
- **The durable correctness fact, stated in as many words:** this
reassociation is **NOT bit-identical**. Estrin differs from Horner by
**at most exactly 1 ULP** (1.09% of 404k points, max abs 5.96e-8); vs
f64 truth Horner 5.77e-8 / Estrin 6.55e-8 (both within ~1 ULP of
correctly-rounded erf); large |x| → ±1.0, denormals bit-identical, NaN →
NaN, ±inf → ±1.0. Names the gate test
**`erf_reassociation_costs_no_accuracy`** as the tripwire.

## Validation

Documentation only — no source, no benchmarks re-run. No markdown
linter/build exists in-tree, so there is nothing to build; the change is
prose appended to an existing report.

Refs #1218. Companion to the separate threshold-tuning issue filed for
#1149.

Co-authored-by: justinchuby <223556219+Copilot@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant