//! `p4-bench`: what the board's serial link can actually carry, verified byte for byte. //! //! Two modes, because there are two different questions and conflating them is how this port got //! optimised by guesswork so far. //! //! **`--link` (default) needs `examples/uartperf.zig` flashed.** It measures the CEILING: the wire //! and the UART driver with nothing else running. Every number is checksummed - the board reports a //! CRC over exactly the bytes it received, and the host compares it against a CRC over exactly the //! bytes it sent. An unverified throughput figure is a guess about how fast data was corrupted, //! and on this UART the failure that matters is a silent RX overrun, which a byte count cannot see. //! //! **`--editor` needs the editor flashed.** It measures how much of that ceiling pardes uses, by //! typing at rising rates until it falls behind. There is no protocol available here - the board is //! running an editor, and its answer to a keystroke is a screen update - so this half is timing //! only, and it is honest about that. //! //! The uplink figure is measured to `tcdrain`, not to the last `write`. A write returns once the //! kernel has accepted the bytes, which at 115200 is long before they are on the wire; timing to the //! write would report the speed of memcpy into a tty buffer. const std = @import("std"); const serial = @import("serial.zig"); const proto = @import("perfproto"); const rtt = @import("rtt.zig"); const Mode = enum { /// Verified bulk throughput and latency against `examples/uartperf.zig`. The ceiling. link, /// Keystroke latency against the editor, plus the rate ladder. editor, /// A named experiment: one controlled variable, many trials, machine-readable. sweep, /// Behaviour rather than speed: things that were broken on this transport and must stay fixed. check, }; /// Which variable an experiment varies. One per run, because the point is a controlled variable and /// a session that changed two things at once would not answer either question. const Sweep = enum { /// Screen area, over an in-band resize. Tests whether per-keystroke cost is paid per CELL. geometry, /// Characters already in the line before the measured keystroke. Tests whether an edit is O(n) /// in the buffer - `modal.spliceAlloc` copies the whole content per keystroke, so it should be. length, /// One-off operations at a fixed geometry: motions, an insert, and a forced full repaint. ops, /// WHERE in a fixed line the edit happens. The length sweep shows cost rising with the line, /// but a line's length and the cursor's column grow together while typing, so that experiment /// cannot tell "the document is big" from "the cursor is far along it". This one holds the /// document constant at one long line and moves only the column, which separates them: a cost /// that follows the column is a walk from the start of the line (grapheme/width iteration), and /// a cost that does not is proportional to the document itself. position, }; /// Widths and signed integers do not mix in Zig 0.16: `printIntAny` emits an explicit `+` for any /// non-negative SIGNED value whenever a width is given (`std/Io/Writer.zig:1548-1559` - the plus is /// omitted only when `width` is null or zero). Every number here is a duration or a count that /// cannot be negative, so they are printed as unsigned and the tables line up. fn pos(x: i64) u64 { return @intCast(@max(0, x)); } const Options = struct { port: []const u8 = "/dev/ttyUSB0", baud: serial.Baud = .b115200, mode: Mode = .link, /// Payload bytes per direction for the bulk tests. 64 KiB is ~5.7 s each way at 115200 - long /// enough that start-up transients do not dominate, short enough to rerun after every change. bulk: u32 = 64 * 1024, /// Round trips for the latency figure. samples: u32 = 32, no_reset: bool = false, which: Sweep = .geometry, /// Trials per condition. Medians over an odd count, so the reported value is a real sample and /// not an average smeared across a transient. repeat: u32 = 5, /// Emit one CSV row per trial instead of a table. Raw trials, not summaries: the analysis should /// be able to see the spread and recompute any statistic, and a tool that only prints medians /// has thrown that away. csv: bool = false, /// Stamped into every CSV row, so a file of results records the build it came from rather than /// relying on the order the runs happened in. label: []const u8 = "-", }; pub fn main(init: std.process.Init.Minimal) void { var o: Options = .{}; var it: std.process.Args.Iterator = .init(init.args); _ = it.skip(); while (it.next()) |a| { if (eql(a, "-h") or eql(a, "--help")) return usage(); if (eql(a, "--no-reset")) { o.no_reset = true; continue; } if (eql(a, "--link")) { o.mode = .link; continue; } if (eql(a, "--editor")) { o.mode = .editor; continue; } if (eql(a, "--check")) { o.mode = .check; continue; } if (eql(a, "--csv")) { o.csv = true; continue; } const val = it.next() orelse fatal("that flag needs a value"); if (eql(a, "--port")) { o.port = val; } else if (eql(a, "--baud")) { const rate = std.fmt.parseInt(u32, val, 10) catch fatal("--baud must be a number"); o.baud = std.enums.fromInt(serial.Baud, rate) orelse fatal("unsupported baud"); } else if (eql(a, "--bulk")) { o.bulk = std.fmt.parseInt(u32, val, 10) catch fatal("--bulk must be a number"); } else if (eql(a, "--samples")) { o.samples = std.fmt.parseInt(u32, val, 10) catch fatal("--samples must be a number"); } else if (eql(a, "--repeat")) { o.repeat = std.fmt.parseInt(u32, val, 10) catch fatal("--repeat must be a number"); } else if (eql(a, "--label")) { o.label = val; } else if (eql(a, "--sweep")) { o.mode = .sweep; o.which = std.meta.stringToEnum(Sweep, val) orelse fatal("--sweep takes geometry, length or ops"); } else fatal("unrecognised argument; try --help"); } run(o) catch |err| switch (err) { error.AccessDenied => { out("p4-bench: cannot open the port: AccessDenied\n\n"); out(serial.access_denied_help); out("\n"); std.process.exit(1); }, error.NoMarker => fatal( \\the board never printed its readiness marker after reset. \\ \\ Expected `MARK UARTPERF_READY` within 25 s. Flash the responder: \\ zig build flash -Dapp=examples/uartperf.zig ), error.NoResponder => fatal( \\the board is not answering the measurement protocol. \\ \\ Flash the responder first: \\ zig build flash -Dapp=examples/uartperf.zig \\ Or measure the editor instead: \\ p4-bench --editor ), error.NoEditor => fatal( \\the board never reached the editor (no `MARK PARDES_READY` within 25 s). \\ \\ zig build flash -Dpardes ), else => { var b: [128]u8 = undefined; fatal(std.fmt.bufPrint(&b, "{s}", .{@errorName(err)}) catch "failed"); }, }; } /// Accumulates bytes off the wire and hands back whole frames. A frame split across reads is the /// normal case on a serial line, so the buffer is the struct rather than a local. const Frames = struct { buf: [proto.header_len + proto.max_payload]u8 = undefined, len: usize = 0, /// Bytes discarded while resynchronising. Nonzero means the stream contained something that was /// not a frame, which is itself a finding. junk: u32 = 0, /// Length of the frame handed out by the last `take`, still occupying the head of the buffer. /// `commit` is what removes it, so a caller may borrow a payload across the call that produced /// it and no further. pending: usize = 0, const Frame = struct { op: proto.Op, payload: []const u8 }; /// The next whole frame, or null on timeout. `payload` borrows the buffer and is invalidated by /// the following call. fn next(f: *Frames, port: *serial.Port, timeout_us: i64) !?Frame { const deadline = nowUs(port) + timeout_us; while (true) { // Serve from what is already buffered before touching the wire: a single read can // deliver several frames, and re-polling between them would add latency that is not // the board's. if (f.take()) |fr| return fr; if (nowUs(port) >= deadline) return null; if (f.len == f.buf.len) { // Full and still not a frame: the buffer holds only junk. Drop one byte so the // resynchronising scan can advance. f.drop(1); continue; } const n = try port.readTimeout(f.buf[f.len..], 2); f.len += n; } } fn take(f: *Frames) ?Frame { while (f.len > 0) { const header = proto.parseHeader(f.buf[0..f.len]) catch { f.resync(); continue; } orelse return null; const total = proto.header_len + @as(usize, header.len); if (f.len < total) return null; const payload = f.buf[proto.header_len..total]; if (proto.crc(payload) != header.crc) { f.resync(); continue; } f.pending = total; return .{ .op = header.op, .payload = payload }; } return null; } /// Advance to the next plausible frame start. Dropping ONE byte per call was the obvious /// spelling and it is far too slow to be correct here: after a reset the buffer holds ~1.4 KB of /// bootloader log, and one byte discarded per poll took longer than the handshake timeout, so a /// working board looked like a missing one. Scanning to the next `P` covers the whole run of /// junk in one step. fn resync(f: *Frames) void { f.junk += 1; const next_magic = std.mem.indexOfScalarPos(u8, f.buf[0..f.len], 1, proto.magic[0]) orelse f.len; f.drop(next_magic); } fn drop(f: *Frames, n: usize) void { const k = @min(n, f.len); std.mem.copyForwards(u8, f.buf[0 .. f.len - k], f.buf[k..f.len]); f.len -= k; } fn commit(f: *Frames) void { if (f.pending > 0) { f.drop(f.pending); f.pending = 0; } } }; fn run(o: Options) !void { var port = try serial.Port.open(o.port, o.baud); defer port.close(); var r: Report = .{}; // No banner in CSV mode: a file of results should be parseable by anything that reads CSV, and // a human-readable header line at the top of it is not. The condition is stamped into every row // by `--label` instead, which survives concatenation of several runs. if (!o.csv) { r.print("p4-bench {s} @ {d} baud wire capacity {d} B/s each way\n\n", .{ o.port, o.baud.rate(), port.capacity(), }); r.flush(); } if (!o.no_reset) try port.resetToRun(.{}); switch (o.mode) { .link => try link(&port, o, &r), .editor => try editor(&port, o, &r), .sweep => try sweep(&port, o, &r), .check => try check(&port, o, &r), } } /// Put the editor in a known state: reached, first frame drawn, insert mode on. /// /// Every experiment starts here, and it matters that it is the same every time. `rtt.roundTrip` /// with an empty stimulus is used as a settle: it sends nothing and returns when the wire has been /// quiet, which is exactly "wait for the board to stop talking". fn ready(port: *serial.Port, o: Options) !void { if (!o.no_reset) try waitFor(port, "MARK PARDES_READY", 25_000); _ = try rtt.roundTrip(port, "", 3_000_000, 300_000); try port.write("i"); _ = try rtt.roundTrip(port, "", 400_000, 250_000); } /// One controlled-variable experiment, emitted as raw trials. /// /// The measured quantity is always the same - the round trip of ONE inserted character - so that /// conditions are comparable. Only the condition changes. fn sweep(port: *serial.Port, o: Options, r: *Report) !void { try ready(port, o); if (o.csv) r.print("label,experiment,cols,rows,length,op,rep,rtt_us,settle_us,bytes\n", .{}); switch (o.which) { // AREA. If a keystroke's cost is paid per cell, halving the rows should roughly halve the // compute. If the cost is per EDIT, geometry will barely move it. The editor clamps itself // to 40x12, so these are all reachable and 40x12 is the ceiling rather than a midpoint. .geometry => { for ([_][2]u16{ .{ 40, 12 }, .{ 40, 8 }, .{ 40, 6 }, .{ 30, 12 }, .{ 20, 12 }, .{ 20, 6 } }) |g| { var buf: [32]u8 = undefined; const resize = std.fmt.bufPrint(&buf, "\x1b[48;{d};{d};0;0t", .{ g[1], g[0] }) catch continue; try port.write(resize); // A resize is a full repaint; let it finish so it is not measured as a keystroke. _ = try rtt.roundTrip(port, "", 3_000_000, 400_000); try trials(port, o, r, .{ .cols = g[0], .rows = g[1], .op = "insert" }); } }, // LENGTH. `modal.spliceAlloc` allocates and copies the whole buffer for every edit, so the // per-keystroke cost should rise with the line. This is the experiment that decides whether // the ~14 ms is a fixed overhead or a function of the document. .length => { var at: u32 = 0; for ([_]u32{ 0, 20, 40, 80, 160, 320, 640 }) |target| { // Type up to the target WITHOUT measuring, so the measured keystroke always sees a // line of exactly `target` characters before it. // Primed in small batches rather than one round trip per character: the priming is // not the measurement, and a round trip each cost 0.3 s, which made the 160-character // condition take minutes. Eight at a time is 8 B on a wire with a 128-byte FIFO, so // nothing can be lost, and one settle per batch keeps the board from queueing. while (at < target) { const batch: u32 = @min(8, target - at); var fill: [8]u8 = @splat('y'); try port.write(fill[0..batch]); _ = try rtt.roundTrip(port, "", 2_000_000, 120_000); at += batch; } try trials(port, o, r, .{ .length = target, .op = "insert" }); } }, // OPS. Not a sweep of a number but of a KIND, to separate "an edit" from "a motion" from // "everything changed". Repeated, because the one-shot table showed 40-byte motions costing // the same round trip as 81-byte inserts and that needs more than one sample to assert. .ops => { try port.write("\x1b"); // motions must be motions _ = try rtt.roundTrip(port, "", 400_000, 250_000); for ([_]struct { name: []const u8, keys: []const u8 }{ .{ .name = "motion_h", .keys = "h" }, .{ .name = "motion_l", .keys = "l" }, .{ .name = "line_start", .keys = "0" }, .{ .name = "line_end", .keys = "$" }, .{ .name = "insert_esc", .keys = "ix\x1b" }, .{ .name = "repaint_39", .keys = "\x1b[48;12;39;0;0t" }, .{ .name = "repaint_40", .keys = "\x1b[48;12;40;0;0t" }, }) |p| { try trials(port, o, r, .{ .op = p.name, .keys = p.keys }); } }, // POSITION. One 320-character line, built once, then the cursor is parked at three places // in it and the SAME single-character insert is timed at each. The document never changes, // so anything that moves is a function of where the cursor is, not of how much text exists. .position => { var built: u32 = 0; while (built < 320) { const batch: u32 = @min(8, 320 - built); var fill: [8]u8 = @splat('y'); try port.write(fill[0..batch]); _ = try rtt.roundTrip(port, "", 2_000_000, 120_000); built += batch; } // Leave insert mode so `0`, `$` and `h` are motions, then for each position re-enter // insert exactly at it. `i` inserts before the cursor, so the column IS the parked one. try port.write("\x1b"); _ = try rtt.roundTrip(port, "", 400_000, 250_000); for ([_]struct { name: []const u8, go: []const u8, col: u32 }{ .{ .name = "col_end", .go = "$", .col = 320 }, .{ .name = "col_start", .go = "0", .col = 0 }, .{ .name = "col_end_again", .go = "$", .col = 320 }, }) |p| { try port.write(p.go); _ = try rtt.roundTrip(port, "", 400_000, 250_000); try port.write("i"); _ = try rtt.roundTrip(port, "", 400_000, 250_000); try trials(port, o, r, .{ .length = p.col, .op = p.name }); // Undo the insertions this condition made, so the next one starts from the same // document. Backspace as many times as there were trials. for (0..@min(o.repeat, 64)) |_| { _ = try rtt.roundTrip(port, "\x7f", 2_000_000, 120_000); } try port.write("\x1b"); _ = try rtt.roundTrip(port, "", 400_000, 250_000); } }, } } const Condition = struct { cols: u16 = 0, rows: u16 = 0, length: u32 = 0, op: []const u8, /// The stimulus. Defaults to one inserted character, which is the comparable unit. keys: []const u8 = "x", }; /// `o.repeat` trials of one condition. Raw rows in CSV mode; median in table mode. fn trials(port: *serial.Port, o: Options, r: *Report, c: Condition) !void { var rtts: [64]i64 = undefined; var got: u32 = 0; var lost: u32 = 0; var last_bytes: usize = 0; var last_settle: i64 = 0; const n = @min(o.repeat, 64); for (0..n) |rep| { const s = try rtt.roundTrip(port, c.keys, 3_000_000, 250_000); if (s) |v| { if (got < 64) { rtts[got] = v.rtt_us; got += 1; } last_bytes = v.bytes; last_settle = v.settle_us; if (o.csv) r.print("{s},{s},{d},{d},{d},{s},{d},{d},{d},{d}\n", .{ o.label, @tagName(o.which), c.cols, c.rows, c.length, c.op, rep, pos(v.rtt_us), pos(v.settle_us), v.bytes, }); } else lost += 1; r.flush(); } if (o.csv) return; if (got == 0) { r.print(" {s:<12} {d:>3}x{d:<3} len {d:>4} no response\n", .{ c.op, c.cols, c.rows, c.length }); return; } std.mem.sort(i64, rtts[0..got], {}, std.sort.asc(i64)); r.print(" {s:<12} {d:>3}x{d:<3} len {d:>4} median {d:>7} us spread {d:>6} us {d:>5} B\n", .{ c.op, c.cols, c.rows, c.length, pos(rtts[got / 2]), pos(rtts[got - 1] - rtts[0]), last_bytes, }); r.flush(); } fn link(port: *serial.Port, o: Options, r: *Report) !void { if (!o.no_reset) { try waitFor(port, "MARK UARTPERF_READY", 25_000); // The bootloader's log is not ours and it is still arriving. Feeding ~1.4 KB of text to a // frame parser wastes the handshake window resynchronising through it. port.drain(); } var frames: Frames = .{}; // A ping proves the responder is there and the framing agrees, before anything is timed. // // Retried, because the first one after a reset can genuinely be lost: the board prints its // marker from `zig_main` and the host answers within microseconds, while the board is still // inside `write` pushing the rest of that string through a 128-byte FIFO. Its RX FIFO holds the // ping meanwhile, but a `source`-sized burst is not the only thing that can outlast one - and a // measuring instrument that fails on a startup race would be reporting its own bug as the // board's. { var buf: [proto.header_len + 8]u8 = undefined; const ping = proto.encode(&buf, .ping, "handshake"[0..8]); var tries: u32 = 0; while (true) : (tries += 1) { if (tries == 5) return error.NoResponder; try port.write(ping); const fr = (try frames.next(port, 500_000)) orelse continue; const ok = fr.op == .pong and std.mem.eql(u8, fr.payload, "handshake"[0..8]); frames.commit(); if (ok) break; } } // ---- UPLINK: host -> board, verified by the board's CRC over what arrived. var chunk: [proto.max_payload]u8 = undefined; var frame: [proto.header_len + proto.max_payload]u8 = undefined; var sent: u32 = 0; var hash: std.hash.Crc32 = .init(); const t_up = nowUs(port); while (sent < o.bulk) { const take: u32 = @min(@as(u32, proto.max_payload), o.bulk - sent); proto.fillPattern(chunk[0..take], sent); hash.update(chunk[0..take]); try port.write(proto.encode(&frame, .sink, chunk[0..take])); sent += take; } // A write returns once the kernel has the bytes, not once the wire does; without this the // uplink figure was 202% of the link's capacity. port.flushOutput(); const up_us = @max(1, nowUs(port) - t_up); const want_crc = hash.final(); try port.write(proto.encode(&frame, .report, "")); const up_stat = blk: { while (true) { const fr = (try frames.next(port, 3_000_000)) orelse return error.NoResponder; if (fr.op == .stat) { const s = proto.Stat.decode(fr.payload) orelse return error.NoResponder; frames.commit(); break :blk s; } frames.commit(); } }; const up_ok = up_stat.bytes == sent and up_stat.crc == want_crc; r.print(" uplink host -> board\n", .{}); r.print(" {d} B in {d} us = {d} B/s ({d}% of wire)\n", .{ sent, up_us, @divTrunc(@as(i64, sent) * 1_000_000, up_us), @divTrunc(@as(i64, sent) * 1_000_000 * 100, up_us * @as(i64, port.capacity())), }); if (up_ok) { r.print(" VERIFIED crc 0x{x:0>8} over {d} B\n", .{ up_stat.crc, up_stat.bytes }); } else { r.print(" FAILED board got {d} B crc 0x{x:0>8}; host sent {d} B crc 0x{x:0>8}", .{ up_stat.bytes, up_stat.crc, sent, want_crc, }); if (up_stat.bytes < sent) r.print(" <-- {d} B LOST", .{sent - up_stat.bytes}); r.print("\n", .{}); } if (up_stat.bad_frames > 0) r.print(" {d} frames arrived corrupt\n", .{up_stat.bad_frames}); if (up_stat.tx_dropped > 0) r.print(" board dropped {d} B on transmit\n", .{up_stat.tx_dropped}); r.flush(); // ---- DOWNLINK: board -> host, verified by the host's CRC over what arrived. var req: [4]u8 = undefined; std.mem.writeInt(u32, &req, o.bulk, .little); const t_down = nowUs(port); try port.write(proto.encode(&frame, .source, &req)); var got: u32 = 0; var down_hash: std.hash.Crc32 = .init(); var down_stat: ?proto.Stat = null; var last = t_down; while (down_stat == null) { const fr = (try frames.next(port, 5_000_000)) orelse break; switch (fr.op) { .data => { got += @intCast(fr.payload.len); down_hash.update(fr.payload); last = nowUs(port); }, .stat => down_stat = proto.Stat.decode(fr.payload), else => {}, } frames.commit(); } const down_us = @max(1, last - t_down); const mine = down_hash.final(); r.print("\n downlink board -> host\n", .{}); r.print(" {d} B in {d} us = {d} B/s ({d}% of wire)\n", .{ got, down_us, @divTrunc(@as(i64, got) * 1_000_000, down_us), @divTrunc(@as(i64, got) * 1_000_000 * 100, down_us * @as(i64, port.capacity())), }); if (down_stat) |s| { if (s.bytes == got and s.crc == mine) { r.print(" VERIFIED crc 0x{x:0>8} over {d} B\n", .{ mine, got }); } else { r.print(" FAILED board sent {d} B crc 0x{x:0>8}; host got {d} B crc 0x{x:0>8}", .{ s.bytes, s.crc, got, mine, }); if (got < s.bytes) r.print(" <-- {d} B LOST", .{s.bytes - got}); r.print("\n", .{}); } } else r.print(" FAILED no closing stat frame\n", .{}); if (frames.junk > 0) r.print(" {d} resynchronisation events on the host\n", .{frames.junk}); r.flush(); // ---- LATENCY: a verified round trip, so a lost ping is distinguishable from a slow one. var min: i64 = std.math.maxInt(i64); var max: i64 = 0; var sum: i64 = 0; var ok: u32 = 0; var lost: u32 = 0; for (0..o.samples) |_| { const t0 = nowUs(port); try port.write(proto.encode(&frame, .ping, "ping")); var answered = false; while (try frames.next(port, 500_000)) |fr| { const was_pong = fr.op == .pong and std.mem.eql(u8, fr.payload, "ping"); frames.commit(); if (was_pong) { answered = true; break; } } if (!answered) { lost += 1; continue; } const dt = nowUs(port) - t0; min = @min(min, dt); max = @max(max, dt); sum += dt; ok += 1; } r.print("\n round trip 13 B out, 13 B back\n", .{}); if (ok > 0) { r.print(" min {d} us mean {d} us max {d} us ({d} samples, {d} lost)\n", .{ pos(min), pos(@divTrunc(sum, ok)), pos(max), o.samples, lost, }); r.print(" wire floor for 26 B is {d} us; the rest is the board\n", .{ @divTrunc(26 * 1_000_000, @as(i64, port.capacity())), }); } else r.print(" every ping lost\n", .{}); r.flush(); } fn editor(port: *serial.Port, o: Options, r: *Report) !void { if (!o.no_reset) try waitFor(port, "MARK PARDES_READY", 25_000); // Settle the first full frame before anything is timed against it. _ = try rtt.roundTrip(port, "", 2_000_000, 300_000); // The editor is modal: a bare `x` would be a motion. One `i` makes every later `x` an edit, // which is the cheapest change that still forces a real render. try port.write("i"); _ = try rtt.roundTrip(port, "", 300_000, 200_000); const base = try rtt.measure(port, .{ .samples = @min(o.samples, 16), .gap_us = 400_000 }); if (base.median_us < 0) return error.NoEditor; r.print(" editor, uncontended at 2.5 keys/s\n", .{}); r.print(" rtt median {d} us settle {d} us {d} B per keystroke\n\n", .{ pos(base.median_us), pos(base.median_settle_us), base.median_bytes, }); r.print(" keys/s median rtt settle B/key wire lost verdict\n", .{}); r.print(" ---------------------------------------------------------------\n", .{}); r.flush(); const ceiling = base.median_us * 3; var best: i64 = -1; for ([_]i64{ 160, 120, 80, 60, 40, 30, 20, 15, 10 }) |gap_ms| { const s = try rtt.measure(port, .{ .samples = @min(o.samples, 16), .gap_us = gap_ms * 1000, .timeout_us = 1_000_000, }); const rate = @divTrunc(@as(i64, 1000), gap_ms); const pass = s.lost == 0 and s.median_us >= 0 and s.median_us <= ceiling; if (pass) best = rate; r.print(" {d:>7} {d:>9} us {d:>9} us {d:>7} {d:>4}% {d:>5} {s}\n", .{ pos(rate), pos(s.median_us), pos(s.median_settle_us), s.median_bytes, s.wire_percent, s.lost, if (s.lost > 0) "LOST INPUT" else if (pass) "ok" else "behind", }); r.flush(); if (s.lost > 0) break; } r.print("\n", .{}); if (best < 0) { r.print(" CEILING: under 6 keys/s - it kept up at no rate tried.\n", .{}); } else { r.print(" CEILING: {d} keys/s sustained (median rtt within 3x of {d} us).\n", .{ best, base.median_us }); } r.flush(); // ONE-OFF COSTS. Typing turned out to be cheap, so the operations that are not typing are where // "too slow to use" has to live. Each is measured once, in the state the ladder left the buffer // in (a long line of `x`), and the interesting column is bytes: an operation that emits ~1.5 KB // has repainted the whole screen, and at this baud that is 130 ms of wire before anything else // can happen. try port.write("\x1b"); // out of insert mode; motions are motions again _ = try rtt.roundTrip(port, "", 400_000, 250_000); r.print("\n one-off operations (bytes is the tell: ~1.5 KB is a full repaint)\n", .{}); r.print(" operation rtt settle bytes\n", .{}); r.print(" ------------------------------------------------\n", .{}); const probes = [_]struct { name: []const u8, keys: []const u8 }{ .{ .name = "motion h", .keys = "h" }, .{ .name = "motion l", .keys = "l" }, .{ .name = "line start", .keys = "0" }, .{ .name = "line end", .keys = "$" }, .{ .name = "insert char", .keys = "ix\x1b" }, // A geometry change is the one stimulus guaranteed to force a full repaint, so it // calibrates the column: whatever this costs is what "everything changed" costs. .{ .name = "resize 40->39", .keys = "\x1b[48;12;39;0;0t" }, .{ .name = "resize 39->40", .keys = "\x1b[48;12;40;0;0t" }, }; for (probes) |p| { if (try rtt.roundTrip(port, p.keys, 3_000_000, 250_000)) |s| { r.print(" {s:<16} {d:>8} us {d:>9} us {d:>9}\n", .{ p.name, pos(s.rtt_us), pos(s.settle_us), s.bytes, }); } else { r.print(" {s:<16} no response (the editor ignored it)\n", .{p.name}); } r.flush(); } } /// Wait for a plain text marker rather than a fixed delay: a slow boot should lengthen the run, not /// silently start measuring a board that is still in its bootloader. fn waitFor(port: *serial.Port, marker: []const u8, timeout_ms: i64) !void { var at: usize = 0; var buf: [1024]u8 = undefined; const deadline = port.nowMs() + timeout_ms; while (port.nowMs() < deadline) { const n = port.readTimeout(&buf, 200) catch 0; for (buf[0..n]) |b| { if (b == marker[at]) { at += 1; if (at == marker.len) return; } else at = if (b == marker[0]) 1 else 0; } } return error.NoMarker; } const Report = struct { buf: [4096]u8 = undefined, len: usize = 0, fn print(self: *Report, comptime fmt: []const u8, args: anytype) void { const s = std.fmt.bufPrint(self.buf[self.len..], fmt, args) catch return; self.len += s.len; } fn flush(self: *Report) void { out(self.buf[0..self.len]); self.len = 0; } }; fn usage() void { out( \\p4-bench - measure the board's serial link, verified with a checksum \\ \\ p4-bench [--link | --editor | --check] [--port ] [--baud ] \\ [--bulk ] [--samples ] [--no-reset] \\ \\ --link (default) bulk throughput each way plus round-trip latency, every byte \\ checksummed. Needs examples/uartperf.zig flashed. \\ --editor type at rising rates against pardes and report the highest rate it keeps \\ up with. Needs the editor flashed. \\ ); } fn nowUs(port: *serial.Port) i64 { return std.Io.Timestamp.now(port.io, .boot).toMicroseconds(); } const io = std.Io.Threaded.global_single_threaded.io(); const stdout: std.Io.File = .{ .handle = 1, .flags = .{ .nonblocking = false } }; fn out(s: []const u8) void { stdout.writeStreamingAll(io, s) catch {}; } fn fatal(msg: []const u8) noreturn { var b: [512]u8 = undefined; out(std.fmt.bufPrint(&b, "p4-bench: {s}\n", .{msg}) catch "p4-bench: error\n"); std.process.exit(1); } fn eql(a: []const u8, b: []const u8) bool { return std.mem.eql(u8, a, b); } // -------------------------------------------------------------------------------- behaviour checks // // Three things were broken on this transport in ways no latency number could show, and each is // checked here because each was found by hand and would otherwise be found by hand again. /// Read until the wire has been quiet for `quiet_ms`, or `cap_ms` has passed, and return what /// arrived. "Quiet" rather than "for a fixed time" because a burst of six hundred characters is many /// frames and an unknown number of milliseconds; a reply read before those have finished is the /// previous action's output, which is how the first version of these checks fooled itself. fn soak(port: *serial.Port, buf: []u8, quiet_ms: i64, cap_ms: i64) []u8 { var n: usize = 0; const cap = port.nowMs() + cap_ms; var last = port.nowMs(); while (port.nowMs() < cap and n < buf.len) { const got = port.readTimeout(buf[n..], 20) catch 0; if (got > 0) { n += got; last = port.nowMs(); } else if (port.nowMs() - last >= quiet_ms) break; } return buf[0..n]; } /// The last absolute cursor position in `bytes`, as 1-based (row, col). /// /// The board's frames end by positioning the cursor and then padding with repeats of that same /// sequence, so the final CUP in a reply is where the editor put the cursor. That makes the cursor /// an observable: it is how these checks see what the editor did without reconstructing a screen. const Cursor = struct { row: u32, col: u32 }; fn lastCup(bytes: []const u8) ?Cursor { var found: ?Cursor = null; var i: usize = 0; while (i + 3 < bytes.len) : (i += 1) { if (bytes[i] != 0x1b or bytes[i + 1] != '[') continue; var j = i + 2; var row: u32 = 0; var col: u32 = 0; var digits: usize = 0; while (j < bytes.len and bytes[j] >= '0' and bytes[j] <= '9') : (j += 1) { row = row * 10 + (bytes[j] - '0'); digits += 1; } if (digits == 0 or j >= bytes.len or bytes[j] != ';') continue; j += 1; digits = 0; while (j < bytes.len and bytes[j] >= '0' and bytes[j] <= '9') : (j += 1) { col = col * 10 + (bytes[j] - '0'); digits += 1; } if (digits == 0 or j >= bytes.len or bytes[j] != 'H') continue; found = .{ .row = row, .col = col }; i = j; } return found; } /// Everything in `src` that a terminal would have PRINTED, with the escape sequences removed. /// /// Searching the raw stream for a string does not work against this firmware, and the reason is the /// renderer: it emits only the cells that changed, jumping between runs with absolute cursor /// positioning, so a word on screen is frequently not a word on the wire. `deadbeef` came back as /// `dead`, a CUP, then `beef`, and a check looking for the whole token called a working Peek broken. fn stripAnsi(dst: []u8, src: []const u8) []u8 { var n: usize = 0; var i: usize = 0; while (i < src.len) { if (src[i] == 0x1b) { i += 1; if (i < src.len and src[i] == '[') { i += 1; // parameters and intermediates, then one final byte in 0x40..0x7e while (i < src.len and src[i] >= 0x20 and src[i] < 0x40) i += 1; if (i < src.len) i += 1; } else if (i < src.len) i += 1; continue; } if (n < dst.len) { dst[n] = src[i]; n += 1; } i += 1; } return dst[0..n]; } /// Type one of the editor's words into a fresh line, select it, and execute it. Returns everything /// the board sent back. /// /// `o` opens a line below rather than reusing one, so this leaves the boot buffer readable instead of /// overwriting whatever it landed on. `x` selects the line and Tab executes the selection - the same /// two keystrokes a person uses, which is the point: this drives the editor rather than reaching /// behind it. fn runWord(port: *serial.Port, buf: []u8, word: []const u8) ![]u8 { try port.write("\x1b"); _ = soak(port, buf, 150, 1500); try port.write("o"); _ = soak(port, buf, 150, 1500); try port.write(word); _ = soak(port, buf, 200, 3000); try port.write("\x1b"); _ = soak(port, buf, 200, 2000); try port.write("x"); _ = soak(port, buf, 200, 2000); try port.write("\t"); return soak(port, buf, 350, 4000); } fn check(port: *serial.Port, o: Options, r: *Report) !void { try ready(port, o); var buf: [8192]u8 = undefined; var failures: u32 = 0; // 1. A LONE ESCAPE IS STILL THE ESCAPE KEY. // // The shell holds a solitary ESC for a few milliseconds because on this wire the first byte of // every escape sequence arrives alone. The hold must expire, or Escape stops working and the // editor is unusable. Typing `abc`, pressing Escape, then `x` deletes a character in normal // mode; if Escape had been swallowed, the `x` would be inserted instead and show up on the wire. // The oracle is the CURSOR, not the text. The first version asked whether an `x` came back on // the wire, which was true until the boot buffer gained a line beginning "x selects a line" - and // then a passing check started failing for a reason that had nothing to do with Escape. A cursor // column cannot be spelled by the document. // // After `abc`, `0` in NORMAL mode goes to the start of the line, which is the gutter's width plus // one. In insert mode it would insert a `0` and leave the cursor three columns further right. The // two are not close. try port.write("abc"); _ = soak(port, &buf, 150, 1500); try port.write("\x1b"); _ = soak(port, &buf, 150, 1500); try port.write("0"); const after_zero = lastCup(soak(port, &buf, 200, 2000)); const escaped = after_zero != null and after_zero.?.col <= 9; if (after_zero) |at| { r.print(" lone Escape still leaves insert mode {s} (cursor col {d})\n", .{ if (escaped) "ok" else "FAILED", at.col, }); } else r.print(" lone Escape still leaves insert mode FAILED (no reply)\n", .{}); if (!escaped) failures += 1; // 2. AN ESCAPE SEQUENCE SPLIT ACROSS READS PARSES AS ONE EVENT. // // This is the bug that made the mouse look unimplemented. At 115200 the bytes of a report are // 87 us apart, so the board reads them one at a time; a parser that resolves a lone ESC turns // one click into ten key presses, and the `0` among them is "go to column zero" in normal mode, // which is exactly where the cursor kept landing. // // The line has to be long enough to contain the clicked column, or the editor correctly clamps // to the end of the line and the check measures the clamp instead of the parse. try port.write("\x1b"); _ = soak(port, &buf, 150, 1500); try port.write("dd"); _ = soak(port, &buf, 200, 2000); try port.write("i"); _ = soak(port, &buf, 150, 1500); try port.write("abcdefghijklmnopqrstuvwxyz0123"); _ = soak(port, &buf, 250, 3000); try port.write("\x1b"); _ = soak(port, &buf, 200, 2000); const want_col: u32 = 18; var report: [16]u8 = undefined; const click = std.fmt.bufPrint(&report, "\x1b[<0;{d};3M", .{want_col}) catch unreachable; // NO gap between the bytes. The wire already provides one - 87 us - and anything longer than the // shell's hold would expire it, which is the check defeating itself rather than exercising the // fix. One write per byte is what stops them arriving as a single read. for (click) |b| try port.write(&[_]u8{b}); _ = soak(port, &buf, 250, 2000); // The RELEASE is what commits it. A press alone paints the new position and then reverts, because // a press is the start of a drag and the caret does not move until the gesture ends - so a check // that reads the cursor after the press alone measures the revert and calls a working click // broken. This cost an hour. const up = std.fmt.bufPrint(&report, "\x1b[<0;{d};3m", .{want_col}) catch unreachable; for (up) |b| try port.write(&[_]u8{b}); const reply = soak(port, &buf, 250, 2000); const landed = lastCup(reply); const at_col = landed != null and landed.?.col == want_col; if (landed) |at| { r.print(" a click split byte-by-byte lands at {d} {s} (cursor {d},{d})\n", .{ want_col, if (at_col) "ok" else "FAILED", at.row, at.col, }); } else r.print(" a click split byte-by-byte lands at {d} FAILED (no reply)\n", .{want_col}); if (!at_col) failures += 1; // 3. POKE WRITES AND PEEK READS IT BACK. // // The two words that touch the bus, checked against each other, which is the only way to check // either one without a second debugger: a Peek alone cannot tell a correct read from a stuck // one, and a Poke alone cannot tell a write from a no-op. Together the pair is falsifiable. // // 0x5011002c is an LP register that holds a written word - verified by hand on this die before // it went into the boot buffer - so a round trip through it exercises the whole path: the hex // parse with no `0x`, the alignment guard, the volatile store, and the volatile load. // // Typed rather than selected out of the boot buffer, because a check that depends on which line // a command sits on breaks every time that buffer is edited. var plain: [8192]u8 = undefined; const wrote = stripAnsi(&plain, try runWord(port, &buf, "Poke 5011002c deadbeef")); // Poke reports on the message row: `0x5011002c: wrote 0xdeadbeef, reads 0xdeadbeef`. The // read-back is the interesting half - on MMIO it is frequently NOT what was written. // Asserted as two facts rather than one phrase: the message row is 49 columns on this grid, so // `0x5011002c: wrote 0xdeadbeef, reads 0xdeadbeef` can wrap, and a wrapped line puts a row // boundary inside whichever phrase happens to straddle it. const poked = std.mem.indexOf(u8, wrote, "wrote") != null and std.mem.indexOf(u8, wrote, "reads") != null and std.mem.indexOf(u8, wrote, "deadbeef") != null; r.print(" Poke writes a word and reads it back {s}\n", .{if (poked) "ok" else "FAILED"}); if (!poked) failures += 1; var plain2: [8192]u8 = undefined; const peeked = stripAnsi(&plain2, try runWord(port, &buf, "Peek 5011002c")); // A separate command, a separate read, a separate render: this is what proves the word survived // rather than that one function returned its own argument. const still = std.mem.indexOf(u8, peeked, "deadbeef") != null; r.print(" and a later Peek still finds it {s}\n", .{if (still) "ok" else "FAILED"}); if (!still) failures += 1; // 4. A PAD ACTUALLY FLIPS, AND THE FIRMWARE READS IT BACK RATHER THAN ASSUMING IT. // // `Gpio ` crosses the whole seam this check exists for: the editor's word, the C ABI // (`GpioFn`, which is why the ABI version is 2), the firmware's `hal.gpio` configure-and-drive, // the pad, and the level read back out of the output register onto the message row. Nothing // smaller exercises the ABI at all. // // The ORACLE IS THE ALTERNATION, not either answer alone. `0->1` on its own is what a firmware // that printed a hardcoded string would also say; two runs reporting `0->1` then `1->0` can only // come from a level that was stored somewhere and read again. Three runs, so the third confirms // the second was not a coincidence of ordering. // // GPIO33 because `src/oracle/ledc_cases.zig` already documents it as a free pin on this board's // JP1 header - pin 21. GPIO20 is the blink demo's pin and may have a wire on it. var flips: [3][]const u8 = undefined; var flip_text: [3][4096]u8 = undefined; for (&flips, &flip_text) |*f, *dst| { const raw = try runWord(port, &buf, "Gpio 33"); f.* = stripAnsi(dst, raw); } const first_low = std.mem.indexOf(u8, flips[0], "33: 0->1") != null; const alternates = for (flips, 0..) |f, i| { const want = if ((i % 2 == 0) == first_low) "33: 0->1" else "33: 1->0"; if (std.mem.indexOf(u8, f, want) == null) break false; } else true; r.print(" a pad flips and reads back {s}\n", .{if (alternates) "ok" else "FAILED"}); if (!alternates) failures += 1; // A BURST IS NOT CHECKED HERE, deliberately. The bug it would cover - input lost while the // transmitter was full - has a deterministic host test in the editor's own // `../02-pardes-code/src/esp32p4/input_rescue.zig`, run by its `zig build unit-test`, which // loses 67 bytes with the rescue removed and needs no board at all. Every hardware oracle for it // that was tried here was worse than that: the cursor stops being reported past 160 characters // because the wrapped line outgrows the viewport, and a screen reconstruction cannot be rebuilt // mid-session because the board only ever sends what CHANGED. A check that cannot fail honestly // is worse than no check, so this file keeps only the two things hardware alone can answer. r.print("\n {d} failure(s)\n", .{failures}); // Flushed here, not by the caller: these lines ARE the result, and returning an error would // otherwise discard the very output that says which check failed. r.flush(); if (failures > 0) return error.CheckFailed; }