diff options
Diffstat (limited to 'tools')
| -rw-r--r-- | tools/bench_main.zig | 695 | ||||
| -rw-r--r-- | tools/perfproto.zig | 201 | ||||
| -rw-r--r-- | tools/rtt.zig | 170 | ||||
| -rw-r--r-- | tools/serial.zig | 28 |
4 files changed, 1093 insertions, 1 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); +} diff --git a/tools/perfproto.zig b/tools/perfproto.zig new file mode 100644 index 0000000..5223500 --- /dev/null +++ b/tools/perfproto.zig @@ -0,0 +1,201 @@ +//! A small framed protocol for measuring the board's serial link, shared verbatim by the host tool +//! and the firmware that answers it. +//! +//! WHY A PROTOCOL AND NOT A STOPWATCH. Timing an editor's keystrokes measures the editor, the +//! renderer and the link at once, and cannot tell a dropped byte from a slow one: RX overrun on this +//! UART is silent in hardware and uncounted in the driver, so a missing keystroke and a late one look +//! identical from the host. A frame with a length and a checksum turns both into facts. If the CRC +//! matches, every byte of that payload crossed intact; if a frame never completes, bytes were lost +//! and the count says how many. A throughput number that is not checksummed is a guess about how +//! fast data was corrupted. +//! +//! THE SHAPE. One fixed 9-byte header, little-endian, then the payload: +//! +//! "P4" op:u8 len:u16 crc:u32 payload[len] +//! +//! The CRC covers the payload only. The header carries it rather than trailing it so a receiver +//! knows, before it has read a single payload byte, exactly how many to expect and what they must +//! hash to - which is what lets the firmware verify a stream with one 4-byte accumulator and no +//! buffer at all. +//! +//! `max_payload` is 1024 and that is a memory decision, not a wire one. The firmware has a 384 KiB +//! heap it must share with an editor, and a bulk test that needed a 64 KiB frame buffer would be +//! measuring a configuration nobody ships. Bulk transfers are therefore many frames, which is also +//! the honest shape: it is the per-frame overhead a real protocol would pay. +//! +//! Both directions use the same header, and a reply's op has the high bit set, so a stray reply can +//! never be mistaken for a request by a resynchronising receiver. + +const std = @import("std"); + +pub const magic = "P4"; +pub const header_len = 9; +pub const max_payload = 1024; + +pub const Op = enum(u8) { + /// Echo the payload back as `pong`. Both directions verified in one exchange, which is what + /// makes it the right stimulus for a latency measurement. + ping = 1, + /// Payload is data to be consumed. The board accumulates a running count and CRC and answers + /// nothing, so the host can keep the uplink full and measure it without return traffic + /// competing for the same wire. + sink = 2, + /// Ask for the accumulated `sink` count and CRC, then reset them. + report = 3, + /// Payload is a u32 count: send exactly that many pattern bytes back, in `data` frames, + /// followed by a `stat`. + source = 4, + + pong = 0x81, + /// Payload is `Stat`, packed little-endian. + stat = 0x83, + /// A chunk of `source` output. + data = 0x84, + + pub fn isReply(o: Op) bool { + return @intFromEnum(o) & 0x80 != 0; + } +}; + +/// What the board reports about a stream it received or sent. Encoded by hand rather than by +/// `@bitCast` of a packed struct: this crosses between a riscv32 firmware and an x86_64 host, and a +/// layout that depends on either compiler's padding rules is a bug waiting for a target change. +pub const Stat = struct { + /// Payload bytes accumulated. + bytes: u32, + /// CRC-32 over exactly those bytes, in order. + crc: u32, + /// Frames whose CRC did not match. Nonzero means the link corrupted data rather than losing it, + /// which is a different fault with a different fix. + bad_frames: u32, + /// Bytes the firmware's UART driver gave up on writing. Its own counter, surfaced here because + /// the host cannot see it any other way. + tx_dropped: u32, + + pub const encoded_len = 16; + + pub fn encode(s: Stat, out: *[encoded_len]u8) void { + std.mem.writeInt(u32, out[0..4], s.bytes, .little); + std.mem.writeInt(u32, out[4..8], s.crc, .little); + std.mem.writeInt(u32, out[8..12], s.bad_frames, .little); + std.mem.writeInt(u32, out[12..16], s.tx_dropped, .little); + } + + pub fn decode(in: []const u8) ?Stat { + if (in.len < encoded_len) return null; + return .{ + .bytes = std.mem.readInt(u32, in[0..4], .little), + .crc = std.mem.readInt(u32, in[4..8], .little), + .bad_frames = std.mem.readInt(u32, in[8..12], .little), + .tx_dropped = std.mem.readInt(u32, in[12..16], .little), + }; + } +}; + +pub fn crc(bytes: []const u8) u32 { + return std.hash.Crc32.hash(bytes); +} + +/// The deterministic byte at stream offset `i`. +/// +/// A counter would be checksummed correctly by an implementation that lost exactly 256 bytes, and a +/// constant by one that lost any amount. This is an 8-bit xorshift-ish walk whose period is long +/// enough that no realistic loss aligns with it, so the CRC catches a gap wherever it falls. +pub fn patternByte(i: u32) u8 { + var x: u32 = i +% 1; + x ^= x << 7; + x ^= x >> 3; + x ^= x << 5; + return @truncate(x); +} + +pub fn fillPattern(buf: []u8, offset: u32) void { + for (buf, 0..) |*b, k| b.* = patternByte(offset +% @as(u32, @intCast(k))); +} + +/// Write a frame into `out`, returning the used slice. `out` must hold `header_len + payload.len`. +pub fn encode(out: []u8, op: Op, payload: []const u8) []u8 { + std.debug.assert(payload.len <= max_payload); + std.debug.assert(out.len >= header_len + payload.len); + out[0] = magic[0]; + out[1] = magic[1]; + out[2] = @intFromEnum(op); + std.mem.writeInt(u16, out[3..5], @intCast(payload.len), .little); + std.mem.writeInt(u32, out[5..9], crc(payload), .little); + @memcpy(out[header_len..][0..payload.len], payload); + return out[0 .. header_len + payload.len]; +} + +pub const Header = struct { + op: Op, + len: u16, + crc: u32, +}; + +/// Read a header out of `buf`. Returns null when fewer than `header_len` bytes are present, and +/// `error.BadFrame` when the magic or the op is not one of ours - which is how a receiver that has +/// lost sync tells "wait for more" from "throw a byte away and try again". +pub fn parseHeader(buf: []const u8) error{BadFrame}!?Header { + if (buf.len < header_len) return null; + if (buf[0] != magic[0] or buf[1] != magic[1]) return error.BadFrame; + const op = std.enums.fromInt(Op, buf[2]) orelse return error.BadFrame; + const len = std.mem.readInt(u16, buf[3..5], .little); + if (len > max_payload) return error.BadFrame; + return .{ .op = op, .len = len, .crc = std.mem.readInt(u32, buf[5..9], .little) }; +} + +test "a frame round-trips through encode and parseHeader" { + var buf: [header_len + 4]u8 = undefined; + const f = encode(&buf, .ping, "abcd"); + try std.testing.expectEqual(@as(usize, header_len + 4), f.len); + const h = (try parseHeader(f)).?; + try std.testing.expectEqual(Op.ping, h.op); + try std.testing.expectEqual(@as(u16, 4), h.len); + try std.testing.expectEqual(crc("abcd"), h.crc); + try std.testing.expectEqualStrings("abcd", f[header_len..]); +} + +test "a short buffer is incomplete, not invalid" { + var buf: [header_len]u8 = undefined; + const f = encode(&buf, .report, ""); + try std.testing.expectEqual(@as(?Header, null), try parseHeader(f[0 .. header_len - 1])); +} + +test "wrong magic and unknown ops are rejected rather than misread" { + var buf: [header_len]u8 = undefined; + var f = encode(&buf, .report, ""); + f[0] = 'X'; + try std.testing.expectError(error.BadFrame, parseHeader(f)); + f[0] = magic[0]; + f[2] = 0x7f; + try std.testing.expectError(error.BadFrame, parseHeader(f)); +} + +test "a truncated stream is caught by the CRC" { + // Losing bytes is the failure this protocol exists to detect, so prove the checksum notices a + // gap that leaves the length plausible. + var full: [64]u8 = undefined; + fillPattern(&full, 0); + var gapped: [64]u8 = undefined; + fillPattern(gapped[0..32], 0); + fillPattern(gapped[32..], 33); // one byte skipped mid-stream + try std.testing.expect(crc(&full) != crc(&gapped)); +} + +test "the pattern does not repeat inside a byte-aligned loss" { + // A plain counter would hash identically after losing exactly 256 bytes. This must not. + var a: [128]u8 = undefined; + var b: [128]u8 = undefined; + fillPattern(&a, 0); + fillPattern(&b, 256); + try std.testing.expect(crc(&a) != crc(&b)); +} + +test "Stat survives the trip between a riscv32 firmware and an x86_64 host" { + const s: Stat = .{ .bytes = 0x11223344, .crc = 0xdeadbeef, .bad_frames = 7, .tx_dropped = 9 }; + var buf: [Stat.encoded_len]u8 = undefined; + s.encode(&buf); + const back = Stat.decode(&buf).?; + try std.testing.expectEqual(s, back); + try std.testing.expectEqual(@as(?Stat, null), Stat.decode(buf[0 .. Stat.encoded_len - 1])); +} diff --git a/tools/rtt.zig b/tools/rtt.zig new file mode 100644 index 0000000..6ab0d87 --- /dev/null +++ b/tools/rtt.zig @@ -0,0 +1,170 @@ +//! Round-trip time over the board's only I/O channel: stimulus out, first byte back. +//! +//! Two functions, because every proposed fix for "too slow to type in" is a trade whose sign cannot +//! be guessed - a frame-rate cap, draining RX while blocked on TX, coalescing input, raising the +//! baud - and the only honest way to rank them is to measure the same number before and after. +//! +//! WHAT IS BEING TIMED, precisely: the interval from the last byte of a stimulus leaving the host to +//! the FIRST byte of the board's response arriving. That is the latency a human perceives as +//! responsiveness, and it is deliberately not the same as the time to finish repainting: a renderer +//! that starts drawing in 8 ms and takes 130 ms to finish feels immediate, while one that thinks for +//! 130 ms and then paints in 8 ms feels broken, and the two are indistinguishable if you only +//! measure when the wire goes quiet. `settle_us` records the second number so the pair can be read +//! together. +//! +//! Microseconds, not milliseconds: at 115200 baud one byte occupies 87 us, so a millisecond clock +//! quantises this measurement into buckets 11 bytes wide. +//! +//! The caller owns the board's STATE. These functions send bytes and time bytes; they do not know +//! what the editor does with them. A stimulus only produces a response if the editor is in a mode +//! where that keystroke changes the screen - pardes is modal, so a caller measuring keystrokes must +//! put it in insert mode first and must pick a stimulus that is not itself a mode change. + +const std = @import("std"); +const serial = @import("serial.zig"); + +pub const Sample = struct { + /// Stimulus out -> first response byte in. + rtt_us: i64, + /// Stimulus out -> last response byte in, i.e. the wire is free again. + settle_us: i64, + /// How much the board emitted in answer. At 115200 this is also a time: bytes * 87 us. + bytes: usize, +}; + +/// One round trip. Returns null when nothing came back within `timeout_us` - which is a result, not +/// an error: a dropped keystroke looks exactly like this, and it is the thing most worth counting. +/// +/// `quiet_us` decides when the response is over. It must exceed the largest gap the board leaves +/// mid-response; a renderer that pauses to allocate can stall longer than one byte time, and too +/// small a value would split one response into two and report a `settle_us` that is too good. +pub fn roundTrip( + port: *serial.Port, + stimulus: []const u8, + timeout_us: i64, + quiet_us: i64, +) !?Sample { + // Anything still in flight belongs to the previous measurement. Without this the first read + // below returns instantly with stale bytes and reports an RTT near zero. + var drain: [1024]u8 = undefined; + while (try port.readTimeout(&drain, 0) > 0) {} + + try port.write(stimulus); + const t0 = nowUs(port); + + var first: i64 = -1; + var last: i64 = t0; + var bytes: usize = 0; + var buf: [4096]u8 = undefined; + while (true) { + const now = nowUs(port); + if (first < 0) { + if (now - t0 > timeout_us) return null; + } else if (now - last > quiet_us) break; + + // Poll in millisecond units because that is what poll(2) takes; the TIMING above is + // microseconds and independent of this granularity. + const n = try port.readTimeout(&buf, 1); + if (n == 0) continue; + if (first < 0) first = nowUs(port); + bytes += n; + last = nowUs(port); + } + return .{ .rtt_us = first - t0, .settle_us = last - t0, .bytes = bytes }; +} + +pub const Stats = struct { + sent: u32, + /// Stimuli that produced no response at all inside the timeout. On this port that is a dropped + /// keystroke, and it is silent everywhere else in the system. + lost: u32, + min_us: i64, + median_us: i64, + max_us: i64, + /// Median, not mean: one 130 ms full repaint among fifty 9 ms updates should not move the + /// number that describes what typing feels like. + median_settle_us: i64, + median_bytes: usize, + /// Every response byte over the whole run, against the wire's capacity for that wall time. + /// 100% means the link is the limit and no amount of firmware tuning will help. + wire_percent: u32, + + pub fn format(s: Stats, w: *std.Io.Writer) std.Io.Writer.Error!void { + try w.print("{d} samples, {d} lost\n", .{ s.sent, s.lost }); + try w.print(" rtt min {d:>6} us median {d:>6} us max {d:>6} us\n", .{ + s.min_us, s.median_us, s.max_us, + }); + try w.print(" settle median {d} us ({d} B)\n", .{ s.median_settle_us, s.median_bytes }); + try w.print(" wire {d}% of capacity\n", .{s.wire_percent}); + } +}; + +pub const Options = struct { + samples: u32 = 20, + /// One byte that edits text without changing mode. `x` inserts an `x` in insert mode. + stimulus: []const u8 = "x", + /// Gap between stimuli. 80 ms is 12.5 characters a second: brisk human typing, and long enough + /// that a healthy editor finishes one update before the next arrives, so each sample is + /// independent rather than measuring a queue. + gap_us: i64 = 80_000, + timeout_us: i64 = 2_000_000, + quiet_us: i64 = 40_000, +}; + +/// `samples` round trips, summarised. The port must already be open and the board already in a +/// state where `stimulus` changes the screen. +pub fn measure(port: *serial.Port, opts: Options) !Stats { + const cap = 256; + var rtt: [cap]i64 = undefined; + var settle: [cap]i64 = undefined; + var size: [cap]usize = undefined; + var got: u32 = 0; + var lost: u32 = 0; + var total_bytes: usize = 0; + + const n = @min(opts.samples, cap); + const t_start = nowUs(port); + for (0..n) |_| { + if (try roundTrip(port, opts.stimulus, opts.timeout_us, opts.quiet_us)) |s| { + rtt[got] = s.rtt_us; + settle[got] = s.settle_us; + size[got] = s.bytes; + total_bytes += s.bytes; + got += 1; + } else lost += 1; + std.Io.sleep(port.io, .fromMicroseconds(opts.gap_us), .boot) catch {}; + } + const elapsed = @max(1, nowUs(port) - t_start); + + if (got == 0) return .{ + .sent = n, + .lost = lost, + .min_us = -1, + .median_us = -1, + .max_us = -1, + .median_settle_us = -1, + .median_bytes = 0, + .wire_percent = 0, + }; + + std.mem.sort(i64, rtt[0..got], {}, std.sort.asc(i64)); + std.mem.sort(i64, settle[0..got], {}, std.sort.asc(i64)); + std.mem.sort(usize, size[0..got], {}, std.sort.asc(usize)); + + // Bytes per second the wire can carry: baud/10, since each byte is 8N1 = 10 bit times. + const capacity = @as(i64, port.capacity()); + return .{ + .sent = n, + .lost = lost, + .min_us = rtt[0], + .median_us = rtt[got / 2], + .max_us = rtt[got - 1], + .median_settle_us = settle[got / 2], + .median_bytes = size[got / 2], + .wire_percent = @intCast(@divTrunc(@as(i64, @intCast(total_bytes)) * 1_000_000 * 100, elapsed * capacity)), + }; +} + +fn nowUs(port: *serial.Port) i64 { + return std.Io.Timestamp.now(port.io, .boot).toMicroseconds(); +} diff --git a/tools/serial.zig b/tools/serial.zig index 3398a11..7a740cd 100644 --- a/tools/serial.zig +++ b/tools/serial.zig @@ -81,10 +81,17 @@ pub const Port = struct { file: std.Io.File, io: std.Io, saved: Termios2, + /// The rate currently programmed, kept because the wire's capacity in bytes per second is + /// `rate/10` and anything measuring this link against its ceiling needs that number. The + /// kernel would answer a TCGETS2, but a syscall per sample to re-read a value only this file + /// ever changes is worse than a field. + baud: Baud, // std exposes neither these ioctl numbers nor the TIOCM bits. const TIOCEXCL = 0x540C; const TCFLSH = 0x540B; + /// tcdrain, with a nonzero argument. Zero would transmit a break instead. + const TCSBRK = 0x5409; const TCIFLUSH = 0; const TIOCMGET = 0x5415; const TIOCMSET = 0x5418; @@ -132,7 +139,7 @@ pub const Port = struct { // Drop anything the kernel captured at the previous line rate. _ = linux.ioctl(fd, TCFLSH, TCIFLUSH); - return .{ .file = file, .io = io, .saved = saved }; + return .{ .file = file, .io = io, .saved = saved, .baud = baud }; } /// Re-rate an already-open port, leaving the raw-mode flags and the exclusive claim alone. @@ -153,6 +160,25 @@ pub const Port = struct { t.ospeed = baud.rate(); if (@as(isize, @bitCast(linux.ioctl(p.file.handle, Termios2.TCSETSW2, @intFromPtr(&t)))) < 0) return error.SetAttrFailed; + p.baud = baud; + } + + /// Bytes per second the wire can carry: one 8N1 byte occupies ten bit times. + pub fn capacity(p: *const Port) u32 { + return p.baud.rate() / 10; + } + + /// Block until every byte written has physically left the wire - `tcdrain`, spelled as the + /// ioctl because std exposes neither. + /// + /// Distinct from `drain` above in both direction and meaning, which is worth stating because + /// getting them the wrong way round silently invalidates a measurement: `drain` discards what + /// has ARRIVED, this waits for what is LEAVING. A `write` returns once the kernel has accepted + /// the bytes, so timing a transfer to the write measures a memcpy into a tty buffer - at 115200 + /// that reported 202% of the wire's capacity, which is how the confusion was noticed. + pub fn flushOutput(p: *Port) void { + // TCSBRK with a nonzero argument is tcdrain on Linux; with zero it would send a break. + _ = linux.ioctl(p.file.handle, TCSBRK, 1); } pub fn close(p: *Port) void { |
