A measuring instrument, and what it says about where the latency goes

"Too slow for interactive use" is a real complaint and not a number. This adds the
number, and the number says the wire is innocent.

## The instrument

`tools/perfproto.zig` is a small framed protocol - "P4", op, length, CRC-32 of the
payload, payload - shared VERBATIM by the host tool and `examples/uartperf.zig`, so
a frame one writes and the other parses cannot drift. It is imported as a module by
both, not copied.

The checksum is the whole point. RX overrun on this UART is undetected in hardware
and uncounted in the driver, so a byte that never arrived is indistinguishable from
a late one; a throughput figure that is not checksummed is a guess about how fast
data was corrupted. `sink` accumulates a CRC over every payload byte the board
received and `report` hands it back, so the host can prove that what arrived is
what it sent.

`tools/rtt.zig` is the two timing functions: `roundTrip` and `measure`. Round trip
is to the FIRST response byte, deliberately. A renderer that starts drawing in 8 ms
and finishes in 130 ms feels immediate; one that thinks for 130 ms and then draws in
8 ms feels broken; waiting for the wire to fall quiet cannot tell them apart. Time
to the last byte is recorded separately as `settle`. Microseconds, because at 115200
one byte is 87 us and a millisecond clock quantises the answer into buckets eleven
bytes wide.

`tools/bench_main.zig` is `p4-bench`: `--link` for the ceiling, `--editor` for how
much of it the editor uses, `--sweep` for one controlled variable at a time with
`--csv` raw per-trial output.

## What it measured

The link is essentially perfect: 11,496 B/s up and 11,413 B/s down, 99.8% of
capacity in both directions, CRC verified over 32,768 B each way, zero corruption.
Typing at 6 to 100 keys/s loses nothing and never uses more than 9% of the wire, so
H5 - "typing loses input" - is refuted.

Latency is compute per input event, not transmission. A 40-byte motion and a
206-byte insert-and-escape cost the SAME round trip to within 0.3 ms, across a
five-fold range of output. That is why raising the baud cannot fix typing: there is
almost no wire in it.

And an edit costs the whole document. Round trip against characters already in the
line is a straight line at 54.3 us per character per keystroke - 17.0 ms at an empty
line, 25.6 ms at 160. On a ~90 MHz core that is ~5,000 cycles per character, far
more than a copy alone, so the full-buffer copy the source does is accompanied by at
least one more full pass.

One controlled intervention: building the editor object ReleaseFast instead of
ReleaseSmall cuts the fixed cost 13% and the per-character cost 36%, for 35% more
flash (809,536 B of a 1,536,000 B partition). Its advantage grows with the document.
Nothing else measured comes close to that ratio.

## Three bugs found while building it

The responder printed garbage and looked dead: it read `.rodata` before evicting the
bootloader's stale cache lines. `flushFlashCache` moved from `src/pardes/app.zig` to
`soc.zig` with its measured evidence, since every application that touches `.rodata`
after hand-over needs it and exactly one file knew that.

Then it booted, printed its marker and went silent after ten seconds:
`rst:0x10 (CHIP_LP_WDT_RESET)`. The bootloader arms the RTC watchdog and expects the
application to take it over. Only the editor ever did.

`serial.Port.drain()` drains INPUT, not output - so timing a transfer to it reported
202% of the wire's capacity and ate the reply. Added `flushOutput` (tcdrain), named
so the two cannot be confused again.

Also: Zig 0.16 emits an explicit `+` for a non-negative SIGNED integer whenever a
width is given (std/Io/Writer.zig:1548-1559), which put a `+` in front of every
number in the first tables.

## The report

`experiments/report.typ` reads the raw CSVs and computes its own figures, so a
re-run changes the document instead of contradicting it. It states five hypotheses,
settles each against one experiment, and is explicit about the one that failed: the
geometry sweep is confounded, because characters accumulated across conditions and
the length experiment then proved that matters. It is reported as unsupported rather
than dressed up as a result.

1 files changed, 229 insertions, 0 deletions

diff --git a/examples/uartperf.zig b/examples/uartperf.zig
new file mode 100644
index 0000000..339f642
--- /dev/null
+++ b/examples/uartperf.zig
@@ -0,0 +1,229 @@
+//! The board half of the link measurement: answer `tools/perfproto.zig` frames over UART0.
+//!
+//! This is the CEILING the editor is measured against. `p4-bench` against this firmware says what
+//! the wire and the UART driver can do with nothing else running; `p4-bench` against the editor says
+//! how much of that the editor manages to use. Optimising the editor without the first number is
+//! guessing, because at 115200 baud a good deal of what feels slow is simply the wire, and no amount
+//! of firmware work moves it.
+//!
+//! Three things it deliberately does NOT do, each of which would corrupt the number:
+//!
+//!   * **No `soc.rom.print`.** The mask ROM's `ets_printf` formats and then pushes one byte at a
+//!     time, spinning on the FIFO for each - the exact cost this is trying to measure around. Every
+//!     byte here goes through the same batched FIFO path `src/pardes/uart.zig` uses.
+//!   * **No UART reconfiguration.** Not the divider, not the format, not `reset()`. The
+//!     second-stage bootloader configured this block; `hal/uart.zig:195-211` records that resetting
+//!     it returns UART_CLKDIV to its power-on value and takes the session with it.
+//!   * **No allocation.** One parse buffer and one send buffer, both static, both sized by the
+//!     protocol's own `max_payload`. A measurement that shared a heap with anything would measure
+//!     the heap.
+//!
+//! The verification is the point. `sink` accumulates a CRC across every payload byte received and
+//! `report` hands it back, so the host can prove that what arrived is what it sent - at this baud a
+//! silent RX overrun is the failure mode that matters, and a byte count alone cannot see it.
+
+const std = @import("std");
+const hal = @import("hal");
+const proto = @import("perfproto");
+
+const uart0 = hal.uart.Uart.init(0);
+
+/// Room for one whole frame. The protocol caps a payload at 1024 precisely so this can be static.
+var rx: [proto.header_len + proto.max_payload]u8 = undefined;
+var rx_len: usize = 0;
+
+var tx: [proto.header_len + proto.max_payload]u8 = undefined;
+
+/// The running `sink` accumulators, reported and reset by `report`.
+var sunk_bytes: u32 = 0;
+var sunk_crc: std.hash.Crc32 = undefined;
+var bad_frames: u32 = 0;
+var tx_dropped: u32 = 0;
+
+/// Push bytes through the TX FIFO, reading the status once per burst rather than once per byte.
+///
+/// The spin is bounded because an unbounded one is indistinguishable from a hang on a board with no
+/// debugger, and because this program's whole purpose is to report numbers: a wedged transmitter
+/// that increments a counter can still be diagnosed, while one that spins forever cannot.
+fn write(bytes: []const u8) void {
+    var rest = bytes;
+    while (rest.len > 0) {
+        var room = uart0.txFree();
+        var spins: u32 = 0;
+        while (room == 0) {
+            spins += 1;
+            if (spins > 1_000_000) {
+                tx_dropped +%= @intCast(rest.len);
+                return;
+            }
+            room = uart0.txFree();
+        }
+        const n = @min(room, rest.len);
+        for (rest[0..n]) |b| uart0.pushByte(b);
+        rest = rest[n..];
+    }
+}
+
+fn send(op: proto.Op, payload: []const u8) void {
+    write(proto.encode(&tx, op, payload));
+}
+
+fn sendStat() void {
+    var buf: [proto.Stat.encoded_len]u8 = undefined;
+    const s: proto.Stat = .{
+        .bytes = sunk_bytes,
+        .crc = sunk_crc.final(),
+        .bad_frames = bad_frames,
+        .tx_dropped = tx_dropped,
+    };
+    s.encode(&buf);
+    send(.stat, &buf);
+    sunk_bytes = 0;
+    sunk_crc = .init();
+    bad_frames = 0;
+}
+
+/// Stream `n` pattern bytes back as `data` frames, then a `stat` whose CRC covers all of them.
+///
+/// Filled a frame at a time from the shared generator rather than from a table: the host computes
+/// the same sequence from the same function, so a disagreement is a real transport fault and not two
+/// copies of a constant drifting apart.
+fn source(n: u32) void {
+    var chunk: [proto.max_payload]u8 = undefined;
+    var sent: u32 = 0;
+    var hash: std.hash.Crc32 = .init();
+    while (sent < n) {
+        const take: u32 = @min(@as(u32, proto.max_payload), n - sent);
+        proto.fillPattern(chunk[0..take], sent);
+        hash.update(chunk[0..take]);
+        send(.data, chunk[0..take]);
+        sent += take;
+    }
+    var buf: [proto.Stat.encoded_len]u8 = undefined;
+    const s: proto.Stat = .{
+        .bytes = sent,
+        .crc = hash.final(),
+        .bad_frames = bad_frames,
+        .tx_dropped = tx_dropped,
+    };
+    s.encode(&buf);
+    send(.stat, &buf);
+}
+
+/// Consume one complete frame from the head of `rx`. Returns the bytes consumed, or 0 when the
+/// frame is not all here yet.
+fn step() usize {
+    const header = proto.parseHeader(rx[0..rx_len]) catch {
+        // Lost sync. Drop ONE byte and let the next call try again from there: the magic is two
+        // bytes, so resynchronising by scanning is the only correct recovery, and dropping the whole
+        // buffer would discard a good frame that happened to follow a corrupt one.
+        return 1;
+    } orelse return 0;
+
+    const total = proto.header_len + @as(usize, header.len);
+    if (rx_len < total) return 0;
+    const payload = rx[proto.header_len..total];
+
+    if (proto.crc(payload) != header.crc) {
+        // Corruption, not loss: the length was plausible and the bytes were not. Counted and
+        // discarded, because acting on it would put the wrong answer in the host's hands.
+        bad_frames +%= 1;
+        return total;
+    }
+
+    switch (header.op) {
+        .ping => send(.pong, payload),
+        .sink => {
+            sunk_bytes +%= header.len;
+            sunk_crc.update(payload);
+        },
+        .report => sendStat(),
+        .source => {
+            const n = if (header.len >= 4) std.mem.readInt(u32, payload[0..4], .little) else 0;
+            source(n);
+        },
+        // Replies are ours to send, never to receive. A reply arriving here means the host is
+        // confused or the wire is looping back; count it rather than answering it.
+        .pong, .stat, .data => bad_frames +%= 1,
+    }
+    return total;
+}
+
+export fn zig_main() noreturn {
+    // FIRST, before any `.rodata` is touched - and the marker below IS `.rodata`. Without this the
+    // bootloader's stale cache lines make that string read as machine code, the board emits noise,
+    // and it looks exactly like a firmware that never started. Measured here before the call was
+    // added: `\xefc\xff\xff\xd5\xb7...` instead of the marker.
+    @import("soc").flushFlashCache();
+
+    // The bootloader arms the RTC watchdog and expects the application to take it over. Nothing in
+    // this repo ever did, so every image here was being reset on a ten-second cycle - invisible to
+    // a program that prints once and spins, and fatal to one that must answer for a minute. It is
+    // why this responder booted, printed its marker, and then went silent: `rst:0x10
+    // (CHIP_LP_WDT_RESET)` in the next boot log, measured.
+    _ = hal.rwdt.disable();
+    sunk_crc = .init();
+
+    // Announce readiness in plain text rather than as a frame: the host watches for this during
+    // reset, while the bootloader's own chatter is still arriving and no frame parser is in sync.
+    write("\r\nMARK UARTPERF_READY\r\n");
+
+    while (true) {
+        // Fill from the FIFO first and always, so the RX FIFO is never left to overflow while this
+        // loop is busy elsewhere. 128 bytes at 115200 is 107 ms of slack and a `source` burst can
+        // hold the transmitter far longer than that, which is exactly the hazard being measured on
+        // the editor - so the measuring instrument must not have it.
+        if (rx_len < rx.len) {
+            const room = rx.len - rx_len;
+            var got: usize = 0;
+            while (got < room and uart0.rxCount() > 0) {
+                rx[rx_len + got] = uart0.popByte();
+                got += 1;
+            }
+            rx_len += got;
+        }
+
+        var off: usize = 0;
+        while (off < rx_len) {
+            const n = step();
+            if (n == 0) break;
+            off += n;
+        }
+        if (off > 0) {
+            std.mem.copyForwards(u8, rx[0 .. rx_len - off], rx[off..rx_len]);
+            rx_len -= off;
+        }
+    }
+}
+
+/// Reset entry, the same shape as every other application here: the bootloader hands over with an
+/// unspecified stack pointer and the FPU off, and `.bss` is not cleared for us. The FPU bit matters
+/// even in a program with no floats, because a generic `bufPrint` instantiation can reach std's
+/// float formatting path - and `std.hash.Crc32`'s table generation is comptime, so nothing here
+/// needs the FPU at run time, but nothing here is worth a trap either.
+export fn _start() linksection(".text.entry") callconv(.naked) noreturn {
+    asm volatile (
+        \\ li t0, 1 << 13
+        \\ csrs mstatus, t0
+        \\ la sp, __stack_top
+        \\ mv fp, sp
+        \\ la t0, __bss_start
+        \\ la t1, __bss_end
+        \\ bgeu t0, t1, 2f
+        \\1:
+        \\ sw zero, 0(t0)
+        \\ addi t0, t0, 4
+        \\ bltu t0, t1, 1b
+        \\2:
+        \\ j zig_main
+    );
+}
+
+/// A panic here would be a measurement that silently stopped, so it says so on the wire it was
+/// measuring - through the ROM's printf, because a panic may well be the UART path itself failing.
+pub const panic = std.debug.FullPanic(struct {
+    fn call(msg: []const u8, _: ?usize) noreturn {
+        @import("soc").rom.print("MARK UARTPERF_PANIC %s\r\n", .{msg.ptr});
+        while (true) {}
+    }
+}.call);