Skip to content

Record the third failure mode: instruments that lie - #729

Merged
justinchuby merged 1 commit into
mainfrom
docs/session-2026-08-06
Aug 7, 2026
Merged

justinchuby merged 1 commit into
mainfrom
docs/session-2026-08-06

Conversation

@justinchuby

Copy link
Copy Markdown
Owner

Consolidating today's findings into the document rather than leaving them in issues.

The new section: a third failure mode

MEMORY_ARCHITECTURE.md already recorded two ways this area fails — code that is right, tested and never reached; and measurements that are reproducible but support a conclusion they do not license. Today produced a third, and it cost more than either.

An instrument that runs, reports a plausible number, and measures the wrong thing.

h2d_enqueue_copy_ms put host-to-device transfer at 1.7% of decode step time. That figure retired an entire line of work — prefetch depth, pinned versus pageable staging, transfer overlap — and was published on #705 and #718.

The arithmetic gives it away: the same step stages 7.33 GiB, and 7.33 GiB in 30 ms would be ~250 GB/s, roughly ten times this machine's PCIe link. The counter bracketed an asynchronous enqueue returning.

The first repair renamed it copy_wait_ms, pointing it at compute_wait_fence — whose own doc comment reads "a stream-ordered, non host-blocking cross-stream wait." The same non-measurement survived under a name that invited the wrong reading more strongly than before. Measured properly with CUDA events, transfer is 18.8%.

Two habits, both cheap:

  • Divide the bytes by the time and ask whether the answer is a real bandwidth. A number near link speed, near memcpy speed, or ten times either tells you what the counter actually bracketed. This is what caught it, and it takes seconds.
  • State on every timing counter exactly what lies between start and stop, and whether anything there blocks the host. Enforced in weight_paging.rs since Speed up CUDA weight offload page-in #715.

The pattern underneath all three

Telemetry that never reaches the operator, three times in one subsystem: documented env vars nothing reads (#688), counters computed and never printed (#719), counters printed with nothing writing them (#715).

The #719 case is the sharpest. A residency cache paging at a 0% hit rate printed a weight-offload section in which every visible row read 0.00 — and my first reading was that the cache was inert. The opposite was true and provably so: the section printing at all required one of the three hidden counters to be non-zero. The instrument reported the exact inverse of what it measured.

After a third instance the response should be a guard, not more vigilance.

Status table rows where today changed the facts

Docs only.

The document already covered code that is right and never reached, and
measurements that support a conclusion they do not license. A third mode
cost more than either today: an instrument that runs, reports a plausible
number, and measures the wrong thing.

h2d_enqueue_copy_ms put host-to-device transfer at 1.7% of step time and
retired an entire line of work on that basis. It bracketed an async
enqueue returning, not a transfer completing. The arithmetic gave it
away: the same step stages 7.33 GiB, and 7.33 GiB in 30 ms is ~250 GB/s,
about ten times this machine's link. The first repair renamed it to
copy_wait_ms around a call whose own doc says "non host-blocking", so the
same non-measurement survived under a name that invited the wrong reading
more strongly. Measured with CUDA events, transfer is 18.8%.

Two habits follow: divide bytes by time and ask whether the answer is a
real bandwidth; and state on every timing counter what lies between start
and stop and whether anything there blocks the host.

Also records the pattern underneath all three - telemetry that never
reaches the operator, now three times in one subsystem - and updates the
status table where today changed the facts: --vram-limit now enforced,
the weight residency cache's 0% hit rate and its fix, the KV page store
contract opening, and captured graphs verified to survive a VMM remap.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot-Session: d60eb808-7cc6-4abc-b48d-2a6dd3841624
@codecov

codecov Bot commented Aug 7, 2026 •

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 80.13%. Comparing base (8d2f64c) to head (3244f0e).

Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff             @@
##             main     #729      +/-   ##
==========================================
- Coverage   80.14%   80.13%   -0.02%     
==========================================
  Files         331      329       -2     
  Lines      132743   130573    -2170     
  Branches   132743   130573    -2170     
==========================================
- Hits       106383   104629    -1754     
+ Misses      22118    21714     -404     
+ Partials     4242     4230      -12     
Flag Coverage Δ
cli-ort-linux 83.37% <ø> (ø)
cli-ort-windows 82.86% <ø> (ø)
mlas ?
offline 79.99% <ø> (+<0.01%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.
see 3 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@github-actions

github-actions Bot commented Aug 7, 2026

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
🔴 matmul/small_generic_bf16_threads=8/1x256x256 35.07 µs 61.64 µs +75.8%
🔴 matmul/medium_generic_f32_threads=1/32x512x512 2.61 ms 3.66 ms +40.5%
🔴 gather/large_f16_threads=1-internal/131072 12.08 µs 16.69 µs +38.1%
⚠️ matmul/medium_generic_f16_threads=8/32x512x512 37.70 µs 47.02 µs +24.7%
⚠️ matmul/large_generic_f32_threads=8/32x1024x1024 4.83 ms 5.92 ms +22.7%
⚠️ gather/medium_f16_threads=1-internal/32768 2.96 µs 3.60 µs +21.7%
⚠️ matmul/small_generic_bf16_threads=1/1x256x256 37.87 µs 44.74 µs +18.1%
✅ qwen3_sampling_processors/top_k_top_p_fast 608.95 µs 690.69 µs +13.4%
✅ matmul/medium_generic_f16_threads=1/32x512x512 35.21 µs 39.32 µs +11.7%
✅ matmul/small_generic_f16_threads=8/1x256x256 34.57 µs 38.25 µs +10.6%
✅ gather/medium_f32_threads=1-internal/32768 5.47 µs 6.03 µs +10.3%
✅ add/large_f16_threads=1-internal/4194304 43.94 ms 46.81 ms +6.5%
✅ matmul/large_generic_bf16_threads=8/32x1024x1024 1.55 ms 1.62 ms +4.8%
✅ matmul/large_generic_f16_threads=1/32x1024x1024 79.45 µs 81.60 µs +2.7%
✅ sampling_latency/min_p_per_token 192.26 µs 197.04 µs +2.5%
✅ add/large_f32_threads=1-internal/4194304 42.47 ms 42.98 ms +1.2%
✅ qwen3_sampling_processors/top_k_full_sort_baseline 1.97 ms 2.00 ms +1.2%
✅ qwen3_sampling_processors/top_k_top_p_full_sort_baseline 5.28 ms 5.34 ms +1.1%
✅ sampling_latency/top_k_per_token 49.33 µs 49.79 µs +0.9%
✅ sampling_latency/top_p_per_token 357.36 µs 360.71 µs +0.9%
✅ kv_cache/alloc_dealloc_pages 36.13 µs 36.13 µs +0.0%
✅ qwen3_sampling_processors/top_p_fast_after_top_k 484.64 µs 483.51 µs -0.2%
✅ grammar_masking/llguidance_compute_mask/32 69.06 µs 68.67 µs -0.6%
✅ matmul/medium_generic_bf16_threads=1/32x512x512 643.46 µs 638.37 µs -0.8%
✅ logit_processing/seven_processor_chain_per_step 297.50 µs 294.87 µs -0.9%
✅ qwen3_sampling_processors/top_p_full_sort_after_top_k_baseline 3.30 ms 3.25 ms -1.5%
✅ matmul/large_generic_bf16_threads=1/32x1024x1024 2.14 ms 2.10 ms -1.6%
✅ gather/large_bf16_threads=1-internal/131072 14.37 µs 14.01 µs -2.5%
✅ qwen3_sampling_processors/top_k_partial_selection 132.88 µs 129.41 µs -2.6%
✅ gather/medium_bf16_threads=1-internal/32768 2.72 µs 2.65 µs -2.9%
✅ tokenization/encode_tokens_per_second 376.61 µs 356.29 µs -5.4%
✅ block_quantized_moe_cached_dense/mxfp4_cached_dense_expert_repeated_call/rows=1,H=256,I=256,E=4,top_k=1 77.57 µs 72.96 µs -5.9%
✅ matmul/large_generic_f16_threads=8/32x1024x1024 98.05 µs 90.01 µs -8.2%
✅ block_quantized_matmul_cached_dense/mxfp4_uncached_dequant_each_call/1x1024x1024 611.51 µs 549.77 µs -10.1%
✅ sampling_latency/greedy_per_token 3.36 µs 3.01 µs -10.5%
✅ gather/small_bf16_threads=1-internal/4096 583.0 ns 516.6 ns -11.4%
✅ add/large_bf16_threads=1-internal/4194304 53.14 ms 46.12 ms -13.2%
✅ add/medium_f16_threads=1-internal/262144 3.38 ms 2.91 ms -13.7%
✅ matmul/small_generic_f32_threads=1/1x256x256 51.87 µs 44.56 µs -14.1%
✅ gather/small_f16_threads=1-internal/4096 552.0 ns 472.3 ns -14.4%
🟢 add/small_bf16_threads=1-internal/1024 14.82 µs 12.58 µs -15.1%
🟢 matmul/small_generic_f16_threads=1/1x256x256 43.89 µs 37.25 µs -15.1%
🟢 add/medium_bf16_threads=1-internal/262144 3.23 ms 2.72 ms -15.8%
🟢 gather/small_f32_threads=1-internal/4096 836.8 ns 697.4 ns -16.7%
🟢 tokenization/decode_tokens_per_second 7.00 ms 5.68 ms -18.8%
🟢 add/medium_f32_threads=1-internal/262144 3.29 ms 2.57 ms -22.0%
🟢 reduce_mean/medium_f32_threads=1-internal/65536 309.61 µs 238.91 µs -22.8%
🟢 reduce_mean/large_f32_threads=1-internal/262144 1.35 ms 1.01 ms -25.3%
🟢 matmul/medium_generic_f32_threads=8/32x512x512 1.73 ms 1.27 ms -26.9%
🟢 gather/large_f32_threads=1-internal/131072 59.13 µs 42.57 µs -28.0%
🟢 block_quantized_moe_cached_dense/mxfp4_uncached_expert_dequant_each_call/rows=1,H=256,I=256,E=4,top_k=1 483.76 µs 347.44 µs -28.2%
🟢 reduce_mean/small_f32_threads=1-internal/4096 19.34 µs 13.88 µs -28.2%
🟢 matmul/large_generic_f32_threads=1/32x1024x1024 13.09 ms 9.14 ms -30.2%
🟢 add/small_f16_threads=1-internal/1024 17.89 µs 12.32 µs -31.1%
🟢 matmul/small_generic_f32_threads=8/1x256x256 69.74 µs 45.05 µs -35.4%
🟢 matmul/medium_generic_bf16_threads=8/32x512x512 699.11 µs 394.11 µs -43.6%
🟢 block_quantized_matmul_cached_dense/mxfp4_cached_dense_repeated_call/1x1024x1024 83.25 µs 46.80 µs -43.8%
🟢 block_quantized_matmul_cached_dense/mxfp4_preexpanded_dense_oncelock_like_proxy/1x1024x1024 90.50 µs 43.88 µs -51.5%
🟢 add/small_f32_threads=1-internal/1024 427.4 ns 180.3 ns -57.8%

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: { 2.93 3.54 7.08 }
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
justinchuby merged commit 05c7282 into main Aug 7, 2026
12 of 15 checks passed
@justinchuby
justinchuby deleted the docs/session-2026-08-06 branch August 7, 2026 05:11
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.

2 participants