diff options
| author | Gabriel Schneider <[email protected]> | 2026-08-25 18:41:18 -0300 |
|---|---|---|
| committer | Gabriel Schneider <[email protected]> | 2026-08-25 18:41:18 -0300 |
| commit | 1cef9c2e4bd873ebe13f5df635899231bcc467d2 (patch) | |
| tree | ce0a9495bc801666ff14da47f7a75728335cc442 /tools/bench_main.zig | |
| parent | ef6f3e460ddbf53a752807bcf10a0fec0a72da7f (diff) | |
| download | esp32p4-1cef9c2e4bd873ebe13f5df635899231bcc467d2.tar.gz esp32p4-1cef9c2e4bd873ebe13f5df635899231bcc467d2.zip | |
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.
Diffstat (limited to 'tools/bench_main.zig')
| -rw-r--r-- | tools/bench_main.zig | 695 |
1 files changed, 695 insertions, 0 deletions
diff --git a/tools/bench_main.zig b/tools/bench_main.zig new file mode 100644 index 0000000..b3470c2 --- /dev/null +++ b/tools/bench_main.zig @@ -0,0 +1,695 @@ +//! `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, +}; + +/// 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, +}; + +/// 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, "--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), + } +} + +/// 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 }); + } + }, + } +} + +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] [--port <path>] [--baud <rate>] + \\ [--bulk <bytes>] [--samples <n>] [--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); +} |
