From 1cef9c2e4bd873ebe13f5df635899231bcc467d2 Mon Sep 17 00:00:00 2001 From: Gabriel Schneider Date: Tue, 25 Aug 2026 18:41:18 -0300 Subject: 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. --- examples/uartperf.zig | 229 ++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 229 insertions(+) create mode 100644 examples/uartperf.zig (limited to 'examples/uartperf.zig') 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); -- cgit v1.3