Stage K-6: riscv64 vblk_io timeouts root-caused and fixed -- time bound, exact used-ring accounting (FABRIC-3.10.8 §4.7)

- Investigation (riscv64): completions are slow, not lost -- up to 15 ms,
  while the ~1M-iteration bound was ~14 ms of guest time. Each timeout
  left the request in the device while the driver forgot it; the next
  request took its used entry as its own and returned before its own I/O
  finished, and so did every later one (394 in one boot), rewriting
  descriptors the device was still reading.
- Fix: VBLK_TIMEOUT_MS (2 s) on the raw hardware counter; each request
  waits for exactly one more used entry; a timed-out request stays
  outstanding and its completion is drained before anything is reused,
  or the next request is refused untouched. Counters for timeouts, late
  drains and busy refusals.
- After the fix, all three ISAs: 0 timeouts, 0 unaccounted completions
  over 1,912 I/Os; riscv64 slowest completion 7.7 ms (was 15.1).
- Standard sequence on amd64/aarch64/riscv64: hash, G, ledger unchanged;
  0 timeouts in the riscv64 log.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

FABRIC-3.10.8.md

@@ -629,3 +629,47 @@ The ledger line is unchanged. **K-5 closes §8 defect 10.**
 **Change** (ruled 2026-09-26). The hosted `Makefile`'s `all` target no longer copies the binary to `lfs/<arch>/starforth`. In this repo the hosted build is a compile-sanity check only, and the copy rewrote the tracked `lfs/amd64/starforth` on every build.
 
 **Evidence:** a forced hosted relink (`touch src/main.c; make`) builds, and `git status` shows no change under `lfs/`. There is no kernel change, so no QEMU acceptance (the hosted build isn't an acceptance target, CLAUDE.md).
+
+### 4.7 K-6 — riscv64 `vblk_io` timeouts: investigated, root-caused, fixed (2026-09-26)
+
+**Investigation** (temporary instrumentation in `vblk_io()`; two riscv64 boots, each running O-A and the standard sequence).
+1. **Poll iterations per completion** (`logs/20260926-064553`, 2,442 I/Os): 413 took ≤10, 20 took ≤1k, 956 took ≤10k, 172 took ≤100k, **878 took 100k–1M**, and 3 timed out. The slowest successful completion took **975,256** iterations, against a bound of 1,048,576. **394 requests started with an unconsumed completion already in the used ring.**
+2. **Time per completion** (`logs/20260926-070007`, 1,808 I/Os, measured on the raw hardware counter): every completion finished within 100 ms, the slowest at **15.1 ms**; 6 timed out. 1M poll iterations take only about 14 ms of guest time on riscv64 TCG.
+
+**Root cause.**
+- **The completions are slow, not lost.** The iteration bound (about 14 ms on riscv64) sat inside the device's latency tail (up to 15 ms), so the slow tail timed out.
+- **Each timeout started a misattribution chain.** A timed-out request stayed in the device, but the driver forgot it. The next request found that request's used entry, took it as its own (the wait loop was "used index changed"), and returned before its own I/O finished. Every later request did the same (394 in one boot).
+  - Reads could return data before the device wrote it.
+  - The next request rewrote descriptors and buffers the device was still reading, which can hand QEMU a malformed chain it drops.
+- This matches the FABRIC-3.md 2026-09-09 report of "a request that never gets a used-ring completion", and why disabling interrupts "made it strictly worse" (interrupts off slows the device-side progress, widening the tail).
+- amd64 and aarch64 were never affected in practice: none of their completions reached the bound.
+
+**Evidence named before the fix:** 0 timeouts on all three ISAs over O-A and the standard sequence; 0 requests starting with an unaccounted completion pending; the completion-latency distribution recorded per ISA.
+
+**Change** (virtio_blk.c).
+- **A time bound**, `VBLK_TIMEOUT_MS` (2 s), measured on the raw hardware counter (`heartbeat_read_counter()` / `timer_tsc_hz()`, readable with interrupts masked). That is over a hundred times the slowest completion measured. A large iteration bound remains as a fallback only if the counter rate is unknown.
+- **Exact accounting.**
+  - Each request waits for exactly **one more** used entry (`last_used_idx + 1`), not "any change".
+  - A request that times out stays outstanding (`late`). The next request first drains its completion, discards it and counts it, before reusing anything.
+  - If the late completion still hasn't come by the deadline, the new request is **refused without touching the queue**, logged and counted.
+- New counters: `virtio_blk_timeouts()`, `virtio_blk_late_consumed()`, `virtio_blk_refused_busy()`.
+
+**Evidence, after the fix** (instrumented builds, O-A plus the standard sequence, 1,912 I/Os on each ISA):
+
+| ISA | log | timeouts / late drained / refused | unaccounted at entry | slowest | ≤100 µs / ≤1 ms / ≤10 ms / ≤1 s |
+|---|---|---|---|---|---|
+| riscv64 | `logs/20260926-071524` | 0 / 0 / 0 | **0** | 7.7 ms | 810 / 120 / 982 / 0 |
+| amd64 | `logs/20260926-072824` | 0 / 0 / 0 | **0** | 189 ms (one outlier) | 817 / 189 / 905 / 1 |
+| aarch64 | `logs/20260926-074136` | 0 / 0 / 0 | **0** | 7.0 ms | 774 / 201 / 937 / 0 |
+
+riscv64's slowest completion halved (15.1 → 7.7 ms), consistent with requests no longer overlapping in the device.
+
+**Standard sequence** (clean build, with the probe reverted; the tree is byte-identical to the saved stage diff).
+
+| ISA | log | result |
+|---|---|---|
+| amd64 | `logs/20260926-075501` | hash `0x99b01134c3d3049c`, G A=40 B=40, all ok `3`, 0 B idle, 0 / 0 |
+| aarch64 | `logs/20260926-080740` | same |
+| riscv64 | `logs/20260926-082042` | same; **0 `timed out` lines in the log** |
+
+**K-6 closes §8 defect 3.**

include/starkernel/virtio_blk.h

@@ -54,4 +54,11 @@
  */
 int virtio_blk_find_artemis(blkio_dev_t *dev_out);
 
+/* FABRIC-3.10.8 K-6 counters: requests that timed out (left outstanding),
+ * late completions drained before a later request, and requests refused
+ * because an earlier one was still in the device. */
+uint64_t virtio_blk_timeouts(void);
+uint64_t virtio_blk_late_consumed(void);
+uint64_t virtio_blk_refused_busy(void);
+
 #endif /* STARKERNEL_VIRTIO_BLK_H */

src/starkernel/virtio/virtio_blk.c

@@ -26,6 +26,7 @@
 #include "blkio.h"
 #include "log.h"
 #include "starkernel/arch.h"
+#include "starkernel/timer.h" /* FABRIC-3.10.8 K-6 -- heartbeat_read_counter(), timer_tsc_hz() */
 
 /* -------------------------------------------------------------------------
  * Virtio 1.0 PCI capability structures
@@ -157,7 +158,10 @@ typedef struct {
     VirtqUsed    *used;
 
     uint16_t avail_idx;
-    uint16_t last_used_idx;
+    uint16_t last_used_idx;   /* used-ring entries consumed so far */
+    uint16_t late;            /* FABRIC-3.10.8 K-6: requests that timed out and
+                               * whose completion hasn't been consumed yet --
+                               * their descriptors may still be in use */
 
     uint64_t capacity_sectors; /* from device config */
     uint32_t total_forth_blocks;
@@ -233,11 +237,65 @@ static inline void rmb(void) {
  * desc[1] = data buffer   (read or write by device)
  * desc[2] = status byte   (written by device)
  * ------------------------------------------------------------------------- */
+/* FABRIC-3.10.8 K-6: a request waits up to VBLK_TIMEOUT_MS for its
+ * completion, measured on the raw hardware counter (readable with
+ * interrupts masked, which they are under the block lock). The bound used
+ * to be ~1M poll iterations: about 14 ms of guest time on riscv64 TCG,
+ * where completions were measured taking up to 15 ms -- so the slow tail
+ * timed out. 2 s is over a hundred times the slowest completion seen. */
+#define VBLK_TIMEOUT_MS 2000u
+
+static uint64_t vblk_timeouts, vblk_late_consumed, vblk_refused_busy;
+uint64_t virtio_blk_timeouts(void)       { return vblk_timeouts; }
+uint64_t virtio_blk_late_consumed(void)  { return vblk_late_consumed; }
+uint64_t virtio_blk_refused_busy(void)   { return vblk_refused_busy; }
+
+/* Wait until the used ring holds `want` entries past last_used_idx.
+ * 0 on success, -1 at the deadline. */
+static int vblk_wait_used(VirtBlkState *s, uint16_t want) {
+    uint64_t hz = timer_tsc_hz();
+    uint64_t t0 = heartbeat_read_counter();
+    uint64_t budget = hz ? (hz / 1000u) * VBLK_TIMEOUT_MS : 0;
+    uint64_t spin = 0x8000000u; /* only if the counter's rate is unknown */
+    while ((uint16_t)(s->used->idx - s->last_used_idx) < want) {
+        rmb();
+        arch_relax(); /* FABRIC-3.md, 2026-09-09: xhci_wait_bit()'s own doc
+                        * comment (xhci.c) has the full reasoning -- a tight
+                        * MMIO-adjacent poll with no yield hint can starve
+                        * TCG's own host-side timer injection. */
+        if (hz ? (heartbeat_read_counter() - t0 >= budget) : (--spin == 0)) return -1;
+    }
+    return 0;
+}
+
 static int vblk_io(int write, uint64_t sector, void *buf, uint32_t nbytes) {
     VirtBlkState *s = &g_vblk;
     VirtqDesc    *d = s->desc;
     int           result;
 
+    /* FABRIC-3.10.8 K-6: a request that timed out may still be in the
+     * device -- reading these descriptors and buffers. Its completion is
+     * drained (and discarded) before anything is reused. It used to be
+     * ignored: the next request then found that stale used entry, took it
+     * as its own and returned before its own I/O had finished, and so did
+     * every request after it (measured: hundreds of requests per riscv64
+     * boot), while the descriptors were rewritten under the device. If the
+     * late completion still hasn't come, this request is refused without
+     * touching the queue. */
+    if (s->late) {
+        if (vblk_wait_used(s, s->late) != 0) {
+            vblk_refused_busy++;
+            log_message(LOG_ERROR,
+                        "virtio_blk: %u earlier request(s) still in the device -- "
+                        "refused (write=%d sector=%llu)",
+                        (unsigned)s->late, write, (unsigned long long)sector);
+            return BLKIO_EIO;
+        }
+        s->last_used_idx = (uint16_t)(s->last_used_idx + s->late);
+        vblk_late_consumed += s->late;
+        s->late = 0;
+    }
+
     /* Fill request header */
     s->req_buf->type     = write ? VIRTIO_BLK_T_OUT : VIRTIO_BLK_T_IN;
     s->req_buf->reserved = 0;
@@ -278,47 +336,31 @@ static int vblk_io(int write, uint64_t sector, void *buf, uint32_t nbytes) {
     *doorbell = 0; /* queue index 0 */
     wmb();
 
-    /* Poll until device posts a used entry.
+    /* Poll until the device posts this request's used entry -- exactly one
+     * past last_used_idx (FABRIC-3.10.8 K-6: it used to be "any change",
+     * which a stale entry satisfied).
      *
-     * FABRIC-3.md, 2026-09-09: live-caught a real request that never gets
-     * a used-ring completion -- root cause not yet isolated (every
-     * existing bounds check, vblk_read()'s own fblock vs total_forth_
-     * blocks and read_devblock_4k()'s own lba vs total_blkio_blocks_1k,
-     * already passed before reaching here, so it isn't a simple out-of-
-     * range request; disabling interrupts around this call was tried and
-     * made it strictly worse -- suggests QEMU's own device-model
-     * completion here depends on guest-visible time/interrupt progress in
-     * this TCG configuration, not a driver-side reentrancy bug -- so that
-     * approach was reverted). spin was 0x2000000 (~33M); at that bound a
-     * single such failure cost tens of real minutes (confirmed: 31+ CPU-
-     * minutes on one boot) because blk_migration_idle_check()'s own scan
-     * calls this per un-cached devblock, up to ~23,000 times a boot, and
-     * apparently more than one of those hits this failure mode. Cut by
-     * ~30x: still enormously generous for a real completion (confirmed
-     * live those return in a handful of iterations, not millions), but
-     * turns what was an effectively-unbounded stall into a fast, loud,
-     * logged failure instead -- callers already tolerate BLKIO_EIO
-     * (zero-fill and move on), they just couldn't afford the old wait to
-     * find that out. */
-    uint32_t spin = 0x100000u; /* ~1M iterations */
+     * History, FABRIC-3.md 2026-09-09: "a real request that never gets a
+     * used-ring completion" was live-caught, and a ~33M-iteration bound
+     * then cost tens of minutes per boot, so the bound was cut to ~1M
+     * iterations. K-6 measured what was happening (FABRIC-3.10.8 §4.7):
+     * riscv64 completions are slow, not lost -- up to 15 ms, just past what
+     * 1M iterations take -- and every timeout left a stale completion that
+     * shifted all later requests by one, rewriting descriptors the device
+     * was still reading. The bound is now time, and a timed-out request
+     * stays outstanding (s->late) until its completion is drained. */
     result = BLKIO_OK;
-    while (s->used->idx == s->last_used_idx) {
-        rmb();
-        arch_relax(); /* FABRIC-3.md, 2026-09-09: xhci_wait_bit()'s own doc
-                        * comment (xhci.c) has the full reasoning -- a tight
-                        * MMIO-adjacent poll with no yield hint can starve
-                        * TCG's own host-side timer injection. */
-        if (!--spin) {
-            log_message(LOG_ERROR,
-                        "virtio_blk: vblk_io timed out (write=%d sector=%llu) -- "
-                        "queue never posted a used entry",
-                        write, (unsigned long long)sector);
-            result = BLKIO_EIO;
-            break;
-        }
+    if (vblk_wait_used(s, 1) != 0) {
+        vblk_timeouts++;
+        s->late = 1;
+        log_message(LOG_ERROR,
+                    "virtio_blk: vblk_io timed out after %u ms (write=%d sector=%llu) -- "
+                    "left outstanding, drained before the next request",
+                    (unsigned)VBLK_TIMEOUT_MS, write, (unsigned long long)sector);
+        return BLKIO_EIO;
     }
-    if (result == BLKIO_OK) {
-        s->last_used_idx = s->used->idx;
+    s->last_used_idx = (uint16_t)(s->last_used_idx + 1u);
+    {
         uint8_t status = *s->status_buf;
         if (status != (uint8_t)VIRTIO_BLK_S_OK) result = BLKIO_EIO;
     }
@@ -500,6 +542,7 @@ static int vblk_init_device(const PciDevice *pci) {
 
     s->avail_idx     = 0;
     s->last_used_idx = 0;
+    s->late          = 0;
 
     /* Wire queue physical addresses into device */
     common->queue_desc   = (uint64_t)(uintptr_t)s->desc;