From ce25f7950234f44dbb67af2cfde8da846d01aeeb Mon Sep 17 00:00:00 2001 From: Gabriel Schneider Date: Tue, 25 Aug 2026 20:20:49 -0300 Subject: Measure inside a frame, and cut a keystroke from 17.0 ms to 8.9 ms The board half of the run to 4 ms: the instrumentation that found the cost, and the measurements that judged each change. `-Dprof` grew two things. It now renders a SECOND time with nothing changed, which splits a frame's cost cleanly: whatever the second render still costs is the price of walking and diffing the whole editor state, and the difference between the two is the price of the change itself. On the die those measured 10.9 ms and 0.1 ms - so 99% of a keystroke was work done regardless of what the keystroke did. It also reads `pardes_p4_frame_prof`, a new export that reports the last frame's three stages in CPU cycles. That is what turned "render is slow" into an address: stage before after copy Surface -> vaxis 6 750 us 1 450 us vaxis diff + emit 2 460 us 2 455 us push into the UART 1 us 1 us (pardes's own Surface build) ~2 600 us ~2 000 us The copy was 57% of a keystroke and it was in this repo's own `present`, not in pardes and not in vaxis. Measured on the die, five document lengths x seven trials per configuration: configuration fixed per char at 160 chars ReleaseSmall 16.99 ms 54.3 us 25.56 ms ReleaseFast 14.85 ms 34.7 us 20.30 ms 0.79x + ASCII grapheme 14.56 ms 12.0 us 16.46 ms 0.64x + ASCII print 14.27 ms 6.9 us 15.36 ms 0.60x + shadow grid 8.87 ms 7.3 us 10.02 ms 0.39x ## Where the remaining 4.9 ms is, and why the goal is not met Round trip is time to the FIRST response byte, so it is ~1.95 ms of host and USB latency plus compute. Compute is now ~6.9 ms and 4 ms needs it under 2.05 ms: a further 3.4x. The three remaining pieces are known and measured - our walk of the grid (1.45 ms), vaxis's own diff and emit (2.46 ms), and pardes rebuilding the whole Surface (~2.0 ms) - and the honest reading is that even a perfect renderer leaves the Surface rebuild, so 4 ms needs pardes to stop rebuilding a whole frame per keystroke. Raising the baud does NOT help this number, and that is worth writing down because it is the obvious next idea: at 115200 an 81-byte reply is 7.0 ms of wire, but almost none of it lands before the first byte. 921600 takes `settle` from 23 ms to ~16 ms and leaves the round trip where it is. ## A bug found on the way `vx.resize` fails on this board. A runtime geometry change takes its allocation failure path, restores the previous size and returns: 80 bytes go out where 1,392 should, and the screen keeps its old shape. Reproduced with the shadow grid compiled out, so it predates it. The board has one geometry per session. That is also why the shadow grid's correctness test compares two firmwares rather than forcing a repaint with a resize - the forcing mechanism does not work here. The reference path and the incremental path were each run against the same 19-step workload and their reconstructed screens are byte-identical. --- experiments/length-RFast-grapheme.csv | 36 +++++++++++++++++++++++++++++++++++ experiments/length-RFast-print.csv | 36 +++++++++++++++++++++++++++++++++++ experiments/length-RFast-shadow.csv | 36 +++++++++++++++++++++++++++++++++++ src/pardes/app.zig | 26 +++++++++++++++++++++++-- 4 files changed, 132 insertions(+), 2 deletions(-) create mode 100644 experiments/length-RFast-grapheme.csv create mode 100644 experiments/length-RFast-print.csv create mode 100644 experiments/length-RFast-shadow.csv diff --git a/experiments/length-RFast-grapheme.csv b/experiments/length-RFast-grapheme.csv new file mode 100644 index 0000000..12c8e0e --- /dev/null +++ b/experiments/length-RFast-grapheme.csv @@ -0,0 +1,36 @@ +label,experiment,cols,rows,length,op,rep,rtt_us,settle_us,bytes +RFast-grapheme,length,0,0,0,insert,0,14885,26233,141 +RFast-grapheme,length,0,0,0,insert,1,14545,20706,80 +RFast-grapheme,length,0,0,0,insert,2,14520,20768,81 +RFast-grapheme,length,0,0,0,insert,3,14539,20675,81 +RFast-grapheme,length,0,0,0,insert,4,14594,20703,81 +RFast-grapheme,length,0,0,0,insert,5,14554,20713,81 +RFast-grapheme,length,0,0,0,insert,6,14611,20738,81 +RFast-grapheme,length,0,0,20,insert,0,14772,21040,81 +RFast-grapheme,length,0,0,20,insert,1,14776,20862,81 +RFast-grapheme,length,0,0,20,insert,2,14709,20938,81 +RFast-grapheme,length,0,0,20,insert,3,14786,20883,81 +RFast-grapheme,length,0,0,20,insert,4,14735,20885,81 +RFast-grapheme,length,0,0,20,insert,5,14865,27951,158 +RFast-grapheme,length,0,0,20,insert,6,14920,20918,80 +RFast-grapheme,length,0,0,40,insert,0,15008,21111,81 +RFast-grapheme,length,0,0,40,insert,1,15018,21143,81 +RFast-grapheme,length,0,0,40,insert,2,15129,21231,81 +RFast-grapheme,length,0,0,40,insert,3,15023,21256,81 +RFast-grapheme,length,0,0,40,insert,4,14965,21150,81 +RFast-grapheme,length,0,0,40,insert,5,15110,21194,81 +RFast-grapheme,length,0,0,40,insert,6,15037,21346,81 +RFast-grapheme,length,0,0,80,insert,0,15558,21725,81 +RFast-grapheme,length,0,0,80,insert,1,15511,21697,81 +RFast-grapheme,length,0,0,80,insert,2,15613,21890,81 +RFast-grapheme,length,0,0,80,insert,3,15580,21874,81 +RFast-grapheme,length,0,0,80,insert,4,15605,21927,81 +RFast-grapheme,length,0,0,80,insert,5,15624,21902,81 +RFast-grapheme,length,0,0,80,insert,6,15540,21793,81 +RFast-grapheme,length,0,0,160,insert,0,16421,22567,81 +RFast-grapheme,length,0,0,160,insert,1,16457,22606,81 +RFast-grapheme,length,0,0,160,insert,2,16391,22541,81 +RFast-grapheme,length,0,0,160,insert,3,16469,22654,81 +RFast-grapheme,length,0,0,160,insert,4,16553,29393,158 +RFast-grapheme,length,0,0,160,insert,5,16451,22687,80 +RFast-grapheme,length,0,0,160,insert,6,16507,22778,81 diff --git a/experiments/length-RFast-print.csv b/experiments/length-RFast-print.csv new file mode 100644 index 0000000..359eb6c --- /dev/null +++ b/experiments/length-RFast-print.csv @@ -0,0 +1,36 @@ +label,experiment,cols,rows,length,op,rep,rtt_us,settle_us,bytes +RFast-print,length,0,0,0,insert,0,14526,25906,141 +RFast-print,length,0,0,0,insert,1,14274,20447,80 +RFast-print,length,0,0,0,insert,2,14333,20546,81 +RFast-print,length,0,0,0,insert,3,14255,20485,81 +RFast-print,length,0,0,0,insert,4,14263,20366,81 +RFast-print,length,0,0,0,insert,5,14229,20380,81 +RFast-print,length,0,0,0,insert,6,14426,20565,81 +RFast-print,length,0,0,20,insert,0,14343,20423,81 +RFast-print,length,0,0,20,insert,1,14435,20550,81 +RFast-print,length,0,0,20,insert,2,14356,20550,81 +RFast-print,length,0,0,20,insert,3,14388,20571,81 +RFast-print,length,0,0,20,insert,4,14325,20626,81 +RFast-print,length,0,0,20,insert,5,14536,27423,158 +RFast-print,length,0,0,20,insert,6,14491,20566,80 +RFast-print,length,0,0,40,insert,0,14460,20702,81 +RFast-print,length,0,0,40,insert,1,14572,20704,81 +RFast-print,length,0,0,40,insert,2,14655,20612,81 +RFast-print,length,0,0,40,insert,3,14511,20822,81 +RFast-print,length,0,0,40,insert,4,14529,20675,81 +RFast-print,length,0,0,40,insert,5,14663,20789,81 +RFast-print,length,0,0,40,insert,6,14555,20622,81 +RFast-print,length,0,0,80,insert,0,14909,21146,81 +RFast-print,length,0,0,80,insert,1,14925,21127,81 +RFast-print,length,0,0,80,insert,2,14850,20923,81 +RFast-print,length,0,0,80,insert,3,14827,21071,81 +RFast-print,length,0,0,80,insert,4,14835,21038,81 +RFast-print,length,0,0,80,insert,5,14909,21055,81 +RFast-print,length,0,0,80,insert,6,14846,21019,81 +RFast-print,length,0,0,160,insert,0,15474,21442,81 +RFast-print,length,0,0,160,insert,1,15334,21479,81 +RFast-print,length,0,0,160,insert,2,15319,21576,81 +RFast-print,length,0,0,160,insert,3,15333,21564,81 +RFast-print,length,0,0,160,insert,4,15521,28310,158 +RFast-print,length,0,0,160,insert,5,15424,21569,80 +RFast-print,length,0,0,160,insert,6,15364,21520,81 diff --git a/experiments/length-RFast-shadow.csv b/experiments/length-RFast-shadow.csv new file mode 100644 index 0000000..280f32b --- /dev/null +++ b/experiments/length-RFast-shadow.csv @@ -0,0 +1,36 @@ +label,experiment,cols,rows,length,op,rep,rtt_us,settle_us,bytes +RFast-shadow,length,0,0,0,insert,0,9358,20630,141 +RFast-shadow,length,0,0,0,insert,1,8889,14840,80 +RFast-shadow,length,0,0,0,insert,2,8854,14972,81 +RFast-shadow,length,0,0,0,insert,3,8812,14915,81 +RFast-shadow,length,0,0,0,insert,4,8835,15076,81 +RFast-shadow,length,0,0,0,insert,5,8939,15056,81 +RFast-shadow,length,0,0,0,insert,6,9017,15114,81 +RFast-shadow,length,0,0,20,insert,0,8914,15153,81 +RFast-shadow,length,0,0,20,insert,1,8982,15181,81 +RFast-shadow,length,0,0,20,insert,2,8968,15200,81 +RFast-shadow,length,0,0,20,insert,3,8913,15315,81 +RFast-shadow,length,0,0,20,insert,4,8967,15203,81 +RFast-shadow,length,0,0,20,insert,5,9172,22033,158 +RFast-shadow,length,0,0,20,insert,6,9074,15112,80 +RFast-shadow,length,0,0,40,insert,0,9137,15276,81 +RFast-shadow,length,0,0,40,insert,1,9134,15288,81 +RFast-shadow,length,0,0,40,insert,2,9180,15368,81 +RFast-shadow,length,0,0,40,insert,3,9176,15398,81 +RFast-shadow,length,0,0,40,insert,4,9171,15214,81 +RFast-shadow,length,0,0,40,insert,5,9236,15299,81 +RFast-shadow,length,0,0,40,insert,6,9280,15378,81 +RFast-shadow,length,0,0,80,insert,0,9496,15693,81 +RFast-shadow,length,0,0,80,insert,1,9492,15601,81 +RFast-shadow,length,0,0,80,insert,2,9463,15571,81 +RFast-shadow,length,0,0,80,insert,3,9527,15734,81 +RFast-shadow,length,0,0,80,insert,4,9487,15662,81 +RFast-shadow,length,0,0,80,insert,5,9483,15633,81 +RFast-shadow,length,0,0,80,insert,6,9508,15636,81 +RFast-shadow,length,0,0,160,insert,0,9982,16123,81 +RFast-shadow,length,0,0,160,insert,1,10180,16184,81 +RFast-shadow,length,0,0,160,insert,2,10023,16239,81 +RFast-shadow,length,0,0,160,insert,3,9989,16163,81 +RFast-shadow,length,0,0,160,insert,4,10161,23035,158 +RFast-shadow,length,0,0,160,insert,5,10022,16060,80 +RFast-shadow,length,0,0,160,insert,6,10178,16294,81 diff --git a/src/pardes/app.zig b/src/pardes/app.zig index 23da203..2f13865 100644 --- a/src/pardes/app.zig +++ b/src/pardes/app.zig @@ -101,6 +101,11 @@ extern fn pardes_p4_wants_frame() callconv(.c) bool; /// Has the user asked to leave? There is nowhere to go, so this only stops the loop. extern fn pardes_p4_quit() callconv(.c) bool; +/// The last frame's three stages in CPU cycles: the copy of pardes's Surface into vaxis's grid, +/// vaxis's own diff-and-emit, and the push into the UART. Only meaningful under `-Dprof`; the +/// editor object always exports it, and it costs two CSR reads per stage. +extern fn pardes_p4_frame_prof(copy: *u64, render: *u64, flush: *u64) callconv(.c) void; + // ------------------------------------------------------------------------------------ the sink /// The write callback handed to `pardes_p4_init`. No context is needed - there is one UART. @@ -230,11 +235,28 @@ export fn zig_main() noreturn { if (err != 0) soc.rom.print("MARK PARDES_RENDER_FAIL rc=%u\r\n", .{err}); if (prof) { const render_cy = soc.cycles() - t0; + // A SECOND render with nothing changed since the first. It splits the cost in two: + // whatever this still costs is the price of walking and diffing the whole editor + // state, paid regardless of output, while the difference between the two is the + // price of the change itself. `wants_frame` is false now, so this only happens + // under -Dprof and never on a shipping build. + const t1 = soc.cycles(); + _ = pardes_p4_render(); + const idle_cy = soc.cycles() - t1; // Reported in cycles, not microseconds: the divisor is the CPU clock, which this // firmware does not set and has only ever measured, so converting here would bake a // guess into the data. `experiments/` divides by the clock it measured. - soc.rom.print("PROF in=%u render=%u\r\n", .{ - @as(u32, @intCast(input_cy)), @as(u32, @intCast(render_cy)), + var copy_cy: u64 = 0; + var vx_cy: u64 = 0; + var flush_cy: u64 = 0; + pardes_p4_frame_prof(©_cy, &vx_cy, &flush_cy); + soc.rom.print("PROF in=%u render=%u idle=%u copy=%u vaxis=%u flush=%u\r\n", .{ + @as(u32, @intCast(input_cy)), + @as(u32, @intCast(render_cy)), + @as(u32, @intCast(idle_cy)), + @as(u32, @intCast(copy_cy)), + @as(u32, @intCast(vx_cy)), + @as(u32, @intCast(flush_cy)), }); } } -- cgit v1.3