Queue output downloads before waiting on the CPU

bench/gguf_latency.md

@@ -42,7 +42,11 @@ MEGANEURA_COOP_F16=1 target/release/examples/gguf_latency model.gguf /tmp/meg 30
 The optional final argument bounds tuning to 30 seconds **per session**;
 the diagnostic allows 256 MiB of scratch so the vocabulary projection is not
 silently excluded by the default 64 MiB limit. Reports record candidates,
-qualification, selections, preparation time and CPU record/wait/readback stages.
+qualification, selections, preparation time and CPU record/finish stages.
+`decode_record_finish_ms` combines waiting and host copying in its second
+interval. The helper uses `Session::wait_read_output`: known staged downloads
+are queued before the CPU wait; initial probes and mapped reads still wait
+first. This does not change the work included in whole-call latency.
 No precision tolerances are changed. Run engines and GPUs sequentially, without
 profilers or builds competing with the timed runs. Repeat in fresh processes
 and reverse their order. First-read mapped/staged qualification is absorbed
@@ -66,6 +70,10 @@ target machine, not selected by a GPU/model table. The API needs initialized
 representative inputs, so ordinary session construction still defaults to
 one submission until this explicit post-initialization search is requested.
 
+The latest [scalar-layout search](scalar-matmul-autotune.md) and
+[queued-readback comparison](queued-readback.md) report fresh-recording results
+on both GPUs. The checkpoints below retain the earlier diagnostic history.
+
 For separate attribution captures, add `MEGANEURA_GPU_TIMING=1` to the Meganeura
 command or `GGML_VK_PERF_LOGGER=1` to llama.cpp. Profiled numbers are not substitute
 latencies: instrumentation changes execution, and Meganeura's pass intervals

bench/gguf_latency.rs

@@ -13,7 +13,7 @@ const DECODE: usize = 32;
 const CONTEXT: usize = 256;
 const SAMPLES: usize = 7;
 
-fn run(session: &mut Session, position: usize, count: usize, vocab: usize) -> (Vec<f32>, [f64; 3]) {
+fn run(session: &mut Session, position: usize, count: usize, vocab: usize) -> (Vec<f32>, [f64; 2]) {
     let tokens: Vec<u32> = (position..position + count)
         .map(|i| 42 + (i % 31) as u32)
         .collect();
@@ -23,18 +23,15 @@ fn run(session: &mut Session, position: usize, count: usize, vocab: usize) -> (V
     let start = Instant::now();
     session.step();
     let submitted = Instant::now();
-    session.wait();
-    let finished = Instant::now();
     let mut logits = vec![0.0; vocab];
-    session.read_output_by_index(0, &mut logits);
+    session.wait_read_output(0, &mut logits);
     assert!(logits.iter().all(|x| x.is_finite()));
     let read = Instant::now();
     (
         logits,
         [
             submitted.duration_since(start).as_secs_f64() * 1000.0,
-            finished.duration_since(submitted).as_secs_f64() * 1000.0,
-            read.duration_since(finished).as_secs_f64() * 1000.0,
+            read.duration_since(submitted).as_secs_f64() * 1000.0,
         ],
     )
 }
@@ -147,7 +144,7 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
         "prompt": PROMPT, "decode": DECODE, "context": CONTEXT, "cache": "f32",
         "vocab": config.vocab_size, "prepare_ms": prepare_ms,
         "prefill_ms": prefill_ms, "decode_ms": decode_ms,
-        "decode_record_wait_read_ms": decode_parts_ms,
+        "decode_record_finish_ms": decode_parts_ms,
         "dispatches": [sessions[1].plan().dispatches.len(), sessions[0].plan().dispatches.len()],
         "tuning": tuning,
         "submission_tuning": scheduling,

bench/queued-readback.md

@@ -0,0 +1,75 @@
+# Queued output readback (2026-09-20)
+
+Implementation: `7c95707b9a69478c1bd498f940b7dde6e851a7e1`, on
+`999bfadff710c67e0c200ca47474551c01dfc4cb`. Model, llama.cpp revision,
+hardware and commands follow the [matched GGUF diagnostic](gguf_latency.md).
+No change to the submitted paper or frozen Inferena cohort.
+
+`Session::wait_read_output` queues a known staged download before the CPU waits
+for graph completion. Both GPUs already select staging for the 196608-byte
+logits. Unknown allocations and mapped reads still wait first. The existing
+readback probe, bit checks and allocation policy are unchanged. All commands
+are freshly recorded; this is not command-buffer replay.
+
+## Isolating the ordering change
+
+The source-only experiment `experiment/overlap-output-readback-2026-09-20`
+(`9f20b35c9805788d9bc35b78c33eae696b5fc405`) runs both readback orders in the
+same tuned sessions. Three fresh processes per GPU, reversing the arm order in
+the middle process; three warmup and seven saved sequences per arm. Builds and
+GPUs run sequentially, without a profiler. CPU affinity is `0,2,4,6,8,10`, with
+unfixed clocks and existing driver caches.
+
+| GPU | Serial decode/token | Queued decode/token | Paired gains |
+| --- | ---: | ---: | --- |
+| RTX 5070 | 1.402 ms | 1.386 ms | 1.37%, 1.17%, 1.65% |
+| Arc B570 | 3.784 ms | 3.653 ms | 2.75%, 4.01%, 3.60% |
+
+Values are medians of process medians. All twelve saved logit sets match bit
+for bit between arms and retain all 33 CPU-reference token choices. Reproduce
+on the experiment branch with `MEGANEURA_COMPARE_READBACK=1`; add
+`MEGANEURA_OVERLAP_READBACK=1` to run queued first. These control switches are
+not in the production helper.
+
+Separate Nsight Systems 2025.5.2 Vulkan/OS-runtime captures use one submission
+per graph and no kernel tuning to check ordering. In the final 32 decode steps,
+the serial path has a host `poll` between graph and readback submissions in
+32/32 cases; the queued path has none. Nsight does not expose the timeline
+semaphore wait itself in these traces. Profiled times are not latency evidence
+and do not measure barrier cost.
+
+## Fresh default-invocation comparison
+
+Three fresh processes per engine and GPU, with rotated engine order. Kernel
+and submission tuning retain their 30-second and two-second per-session
+budgets. Every kernel search visits all eligible classes and all comparisons
+qualify; no kernel search exhausts its budget. Milliseconds, median of process
+medians, including CPU copying of all logits:
+
+| GPU / phase | Meganeura | llama.cpp |
+| --- | ---: | ---: |
+| RTX 5070 prefill | 7.210 | 7.126 |
+| RTX 5070 decode/token | 1.389 | 1.361 |
+| Arc B570 prefill | 14.048 | 15.650 |
+| Arc B570 decode/token | 3.666 | 3.431 |
+
+NVIDIA is about 1.2%/2.0% behind; Intel prefill is 10.2% faster and decode 6.8%
+slower. Decode process medians span 1.346-1.503 ms and 3.656-3.957 ms. The slower
+NVIDIA run keeps eight attention splits instead of sixteen, despite identical
+GEMV choices; Intel's slower run selects two submission chunks instead of four.
+This is evidence to investigate tuning stability, not proof that those choices
+explain every timing difference. The conservative noise guard is unchanged.
+
+All twelve fresh logit sets are finite and retain all 33 CPU-reference choices.
+Maximum per-row relative L2 errors are 0.00000954/0.000178 for Meganeura and
+0.01121/0.01314 for llama.cpp. Median whole preparation is 9.61/31.45 seconds
+for Meganeura and 0.25/0.51 seconds for llama.cpp, with warm driver caches.
+This is one model and batch-one latency, not batched throughput or language
+quality. Intel's secondary PCIe x1 installation limits readback generalization.
+
+All 449 active library tests, all-target/all-feature Clippy and both existing
+device-local regressions pass on both GPUs. The readback regression checks
+fresh GPU writes, empty reads and a partial 16 MiB staging tail. No new test
+executable. Implementation CI passes all six jobs, including host coverage;
+known Naga Workgroup ArrayStride diagnostics remain. Raw data and captures
+stay outside Git.

src/runtime.rs

@@ -6594,6 +6594,27 @@ impl Session {
         self.read_buffer(buf_ref, out);
     }
 
+    /// Wait for pending work and read a graph output.
+    ///
+    /// Queues a staged download before waiting on the CPU. Mapped reads and
+    /// the initial readback probe still wait before accessing the buffer.
+    pub fn wait_read_output(&mut self, index: usize, out: &mut [f32]) {
+        let buf_ref = self.plan.output_buffers[index];
+        let buffer = self.buffers[buf_ref.0 as usize];
+        let staged = !self.logical_host_visible(buf_ref)
+            || self
+                .readback
+                .borrow()
+                .staged
+                .get(&(buffer.data() as usize, std::mem::size_of_val(out)))
+                == Some(&true);
+        if !staged {
+            self.wait();
+        }
+        self.read_buffer(buf_ref, out);
+        self.wait();
+    }
+
     /// Number of graph outputs.
     pub fn num_outputs(&self) -> usize {
         self.plan.output_buffers.len()

tests/device_local.rs

@@ -18,7 +18,7 @@ fn readback_preserves_bits_across_sizes_and_updates() {
     graph.set_outputs(vec![output]);
     let mut session = meganeura::build(&graph, meganeura::SessionConfig::inference_from_env()).0;
     for seed in [0u32, 17] {
-        let values: Vec<_> = (0..len)
+        let mut values: Vec<_> = (0..len)
             .map(|i| {
                 f32::from_bits(match i % 7 {
                     0 => 0x7fc0_0123,
@@ -28,12 +28,13 @@ fn readback_preserves_bits_across_sizes_and_updates() {
                 })
             })
             .collect();
-        session.set_input("x", &values);
-        session.step();
-        session.wait();
         for count in [0, 17, len, 1024, len] {
+            values[3] = f32::from_bits(values[3].to_bits().wrapping_add(1));
+            values[len - 1] = values[3];
+            session.set_input("x", &values);
+            session.step();
             let mut actual = vec![0.0; count];
-            session.read_output_by_index(0, &mut actual);
+            session.wait_read_output(0, &mut actual);
             assert!(
                 actual
                     .iter()