diff --git a/benchmark/latency/README.md b/benchmark/latency/README.md new file mode 100644 index 000000000..7db6e3511 --- /dev/null +++ b/benchmark/latency/README.md @@ -0,0 +1,89 @@ +# Glass-to-pixel latency harness + +The suite in `benchmark/` measures how fast the emulator **consumes** bytes: `cat` a file, +time how long it takes to return. Every number in `benchmark_results/` is of that shape. + +None of it can see the interval that decides whether a terminal feels snappy - the time +between a byte landing in the PTY and the pixel that byte produces. That interval holds the +redraw debounce, the data-stream poll timeout and the whole paint pass, and it is invisible +to a throughput benchmark: an emulator can parse 1.6 GB/s and still wait 50 ms before +drawing any of it. + +This harness measures that interval. + +## What is measured + +Build with the probe compiled in (it always is; it is inert unless the env flag is set) and +launch with `BOSSTERM_FRAME_PROBE=1`. A daemon thread then writes a JSON snapshot once a +second to `~/.bossterm/frame-probe.json`: + +| Field | Meaning | +|---|---| +| `byteToPaintMs` | PTY chunk arrival to the end of the paint pass that first draws it. The number a user feels. | +| `paintCostMs` | Wall time inside `renderTerminal`. Decides whether a throttle is needed at all. | +| `lockedCaptureMs` | UI-thread time holding the terminal buffer lock to capture a frame. Expected to grow with scrollback depth. | +| `drawCallsPerFrame` | `drawText` invocations per paint. The multiplier on text layout cost. | +| `idleFrames` | Paints that drew no newly-arrived data (blink, resize, selection, scroll). | + +Each is `{n, p50, p95, p99, max, mean}`. Latencies are milliseconds. **Report percentiles, +never means** - the tail is what gets noticed. + +### The honest caveat + +`byteToPaintMs` is measured to *draw-issued*, not to photons. It excludes GPU present and +vsync, so it is a **lower bound** on real latency. Two builds measured the same way compare +soundly; an absolute claim about "how many milliseconds a user waits" does not follow from +this number alone and needs the external anchor below. + +## Running it + +```bash +# 1. Launch with the probe on. The user runs the app; nothing here launches it. +BOSSTERM_FRAME_PROBE=1 ./gradlew :bossterm-app:run --no-daemon + +# 2. Zero the histograms immediately before a workload. +./benchmark/latency/probe.sh reset + +# 3. Run one workload in the BossTerm window under test. +./benchmark/latency/workloads.sh keystrokes # (a) 200 single keypresses at a prompt +./benchmark/latency/workloads.sh bulk # (b) cat a 5 MB log +./benchmark/latency/workloads.sh tui # (c) full-screen redraw loop +./benchmark/latency/workloads.sh scroll # (d) full-screen scroll +./benchmark/latency/workloads.sh aged # (e) (b) again, after 10k lines of scrollback + +# 4. Read the result. +./benchmark/latency/probe.sh show +``` + +Workload (e) is the one that exposes scrollback-dependent cost: run it in the *same* tab as +a preceding `bulk`, never a fresh one. + +## What shipped, and what it bought + +Measured on this harness, then made default (no flags remain): + +| change | effect | +|---|---| +| redraw debounce removed (was 8 ms, 50 ms under load) | interactive echo 16.4 ms -> ~2-4 ms | +| `performanceMode` default `balanced` -> `latency` | ~4 ms of that, on its own | +| blanks extend a batched run; ASCII cells skip the grapheme probes | `drawText` 208 -> 30 per frame on `tui`, 176 -> 60 on `scroll` | + +Not fixed, and not a render problem: bulk output still shows a ~1.2 s p95 on a 5 MB `cat`. +`triggerToPaint` there is single-digit milliseconds, so the time is queue wait and parse, +upstream of anything the renderer or the debounce controls. + +## Verifying a renderer change + +A renderer change fails by producing a wrong *picture*, which no unit test sees. Render +`unicode-torture.sh` twice, once before and once after, capture the window both times, and +diff the two images. Check column alignment specifically: a merged glyph run that advances by +font metrics rather than by cell width drifts progressively along a line, which a +whole-image pixel count will not make obvious. + +## External anchor - do this once + +The in-process number is a proxy. Before any conclusion rests on it, confirm it tracks +reality: film ~10 keypresses at a shell prompt with a phone at 240 fps, count frames from +key-down to the glyph appearing, and compare the median against `byteToPaintMs.p50` plus one +frame of present. If they disagree by more than a frame, the probe is wrong and gets fixed +before any tuning decision is made on it. diff --git a/benchmark/latency/probe.sh b/benchmark/latency/probe.sh new file mode 100755 index 000000000..a103b48f8 --- /dev/null +++ b/benchmark/latency/probe.sh @@ -0,0 +1,69 @@ +#!/usr/bin/env bash +# Read and reset the BossTerm frame-latency probe. +# +# The probe writes a JSON snapshot once a second to $BOSSTERM_FRAME_PROBE_OUT, or +# ~/.bossterm/frame-probe.json by default. It only runs when the app was launched with +# BOSSTERM_FRAME_PROBE=1; without that, the file never appears. +set -euo pipefail + +OUT="${BOSSTERM_FRAME_PROBE_OUT:-$HOME/.bossterm/frame-probe.json}" +RESET="$(dirname "$OUT")/frame-probe.reset" + +usage() { + cat <&2 + echo "launch the app with BOSSTERM_FRAME_PROBE=1 and give it a second to sample" >&2 + exit 1 + fi +} + +case "${1:-}" in + reset) + require_snapshot + before=$(stat -f %m "$OUT" 2>/dev/null || stat -c %Y "$OUT") + touch "$RESET" + # The sampler deletes the marker as it zeroes. Waiting for that, rather than + # returning immediately, is what stops a workload from starting against counters + # that still hold the previous run. + for _ in $(seq 1 50); do + if [[ ! -f "$RESET" ]]; then + now=$(stat -f %m "$OUT" 2>/dev/null || stat -c %Y "$OUT") + if [[ "$now" != "$before" ]]; then + echo "reset confirmed" + exit 0 + fi + fi + sleep 0.2 + done + echo "reset marker was not consumed within 10s - is the app running with BOSSTERM_FRAME_PROBE=1?" >&2 + exit 1 + ;; + show) + require_snapshot + cat "$OUT" + ;; + watch) + require_snapshot + while true; do + date +%H:%M:%S + cat "$OUT" + echo + sleep 1 + done + ;; + path) echo "$OUT" ;; + *) usage; exit 1 ;; +esac diff --git a/benchmark/latency/unicode-torture.sh b/benchmark/latency/unicode-torture.sh new file mode 100755 index 000000000..613edcaf8 --- /dev/null +++ b/benchmark/latency/unicode-torture.sh @@ -0,0 +1,32 @@ +#!/usr/bin/env bash +# Every construct the text pass special-cases, on one screen. +# +# The fast text path (blank batching + the ASCII probe skip) is the one change here that can +# fail silently: it produces a WRONG PICTURE rather than a wrong value, so no unit test sees +# it. This fixture exists to be rendered twice, with the fast path off and on, and the two +# frames compared pixel for pixel. +# +# Deliberately heavy on runs of spaces, because that is exactly what blank batching changes: +# aligned columns, indentation, and trailing gaps under an underline. +printf '\033[2J\033[H' +echo "ascii the quick brown fox jumps over the lazy dog 0123456789" +echo "aligned name size modified mode" +echo "aligned src/ 4096 Aug 26 10:11 drwxr-xr-x" +echo "aligned README.md 1024 Aug 26 10:12 -rw-r--r--" +printf 'zwj \xF0\x9F\x91\xA8\xE2\x80\x8D\xF0\x9F\x92\xBB family \xF0\x9F\x91\xA9\xE2\x80\x8D\xF0\x9F\x91\xA9\xE2\x80\x8D\xF0\x9F\x91\xA7 end\n' +printf 'flags \xF0\x9F\x87\xBA\xF0\x9F\x87\xB8 \xF0\x9F\x87\xAF\xF0\x9F\x87\xB5 \xF0\x9F\x87\xAE\xF0\x9F\x87\xB3 end\n' +printf 'skintone \xF0\x9F\x91\x8B\xF0\x9F\x8F\xBD \xF0\x9F\x91\x8D\xF0\x9F\x8F\xBF end\n' +printf 'varsel \xE2\x9C\x94\xEF\xB8\x8F \xE2\x9A\xA0\xEF\xB8\x8F \xE2\x9D\xA4\xEF\xB8\x8F end\n' +printf 'cjk \xE4\xBD\xA0\xE5\xA5\xBD\xE4\xB8\x96\xE7\x95\x8C \xE3\x81\x93\xE3\x82\x93\xE3\x81\xAB\xE3\x81\xA1\xE3\x81\xAF end\n' +printf 'powerline \xEE\x82\xB0 \xEE\x82\xB1 \xEE\x82\xB2 \xEE\x82\xB3 end\n' +printf 'underline \033[4munderlined with gaps\033[0m and \033[4mtrailing \033[0m|\n' +printf 'bold/italic \033[1mbold text\033[0m \033[3mitalic text\033[0m \033[1;3mboth\033[0m\n' +printf 'truecolor ' +for i in 0 1 2 3 4 5 6 7; do printf '\033[38;2;%d;%d;%dm block \033[0m' $((i*31)) $((255-i*31)) $((i*17)); done +printf '\n' +printf 'inverse \033[7m inverse with spaces \033[0m end\n' +printf 'bg runs \033[41m red \033[42m green \033[44m blue \033[0m end\n' +printf 'trailing text with trailing spaces \n' +printf 'leading indented by many spaces\n' +printf 'dim \033[2mdim text here\033[0m end\n' +echo diff --git a/benchmark/latency/workloads.sh b/benchmark/latency/workloads.sh new file mode 100755 index 000000000..241d731e6 --- /dev/null +++ b/benchmark/latency/workloads.sh @@ -0,0 +1,80 @@ +#!/usr/bin/env bash +# Fixed workloads for the frame-latency probe. +# +# Run these INSIDE the BossTerm tab being measured, with the probe reset immediately +# beforehand (`probe.sh reset`). Each one is deterministic so two builds see identical work. +# +# Scope note: the probe stamps a chunk when it ARRIVES from the PTY, so everything here +# measures the output half of the loop (arrival -> pixel). The input half (keypress -> +# PTY write) is not covered by any of these and needs the external camera anchor described +# in README.md. `interactive` is the closest proxy: isolated single-character writes, which +# is the shape a shell echo has, and the case the redraw debounce penalises hardest. +set -euo pipefail + +DURATION_TUI="${DURATION_TUI:-10}" +FIXTURE_DIR="${TMPDIR:-/tmp}/bossterm-latency" +mkdir -p "$FIXTURE_DIR" + +make_log() { + local path="$FIXTURE_DIR/bulk-5mb.log" + if [[ ! -f "$path" ]]; then + # Deterministic content, mixed line lengths and some ANSI colour so the run + # exercises style runs rather than one uniform batch. + awk 'BEGIN { + for (i = 0; i < 60000; i++) { + printf "\033[32m%06d\033[0m INFO module-%02d request completed in %3d ms path=/api/v1/resource/%d\n", i, i % 32, i % 250, i + } + }' > "$path" + fi + echo "$path" +} + +case "${1:-}" in + interactive) + # 200 isolated single-character writes, 50 ms apart. Each one is its own PTY chunk, + # so each pays the full arrival-to-paint cost with no batching to hide behind. + for _ in $(seq 1 200); do + printf 'x' + sleep 0.05 + done + printf '\n' + ;; + bulk) + cat "$(make_log)" + ;; + tui) + # Full-screen repaint loop on the alternate screen: the regime that trips + # HIGH_VOLUME mode (>100 redraws/sec) and drops the terminal to 20 fps. + printf '\033[?1049h' + end=$(( SECONDS + DURATION_TUI )) + frame=0 + while (( SECONDS < end )); do + printf '\033[H' + for row in $(seq 1 40); do + printf '\033[%dm row %02d frame %06d %s\033[0m\n' \ + $(( 31 + (row + frame) % 7 )) "$row" "$frame" \ + 'the quick brown fox jumps over the lazy dog 0123456789' + done + frame=$(( frame + 1 )) + sleep 0.02 + done + printf '\033[?1049l' + echo "tui: $frame frames in ${DURATION_TUI}s" + ;; + scroll) + # Continuous single-line scrolling: every chunk shifts the whole viewport. + for i in $(seq 1 5000); do + printf '\033[36m%05d\033[0m scrolling line with enough width to fill a normal terminal column count\n' "$i" + done + ;; + aged) + # Finding E: the per-frame snapshot walks screen AND full history, so cost is + # expected to rise with scrollback depth. Run in the SAME tab, never a fresh one. + seq 1 10000 | sed 's/^/scrollback filler line /' + cat "$(make_log)" + ;; + *) + echo "usage: workloads.sh {interactive|bulk|tui|scroll|aged}" >&2 + exit 1 + ;; +esac diff --git a/benchmark_results/LATENCY_BASELINE_2026-08-27.md b/benchmark_results/LATENCY_BASELINE_2026-08-27.md new file mode 100644 index 000000000..332c92040 --- /dev/null +++ b/benchmark_results/LATENCY_BASELINE_2026-08-27.md @@ -0,0 +1,222 @@ +# Glass-to-pixel latency: baseline and the debounce removal + +**Date:** 2026-08-27 +**Base:** `perf/terminal-latency`, off `origin/master` @ cacaba54 +**Platform:** macOS (Darwin 25.5.0, Apple Silicon), Compose Multiplatform 1.9.3 +**Method:** `FrameLatencyProbe` + `benchmark/latency/workloads.sh`, one process per config, +probe reset and scrollback wiped before each workload. Figures are milliseconds. + +Latencies are measured to **draw-issued**, excluding GPU present and vsync, so they are a +lower bound. Comparisons between configs are sound; absolute values still want the external +camera anchor described in `benchmark/latency/README.md`. + +--- + +## Finding 0: an occluded window is throttled to ~3 fps, and that swamps everything + +Same workload, same process, only window visibility differing: + +| `tui` | paints | byteToPaint p50 | triggerToPaint p50 | +|---|---|---|---| +| covered by another window | 29 | 294.9 | 294.9 | +| raised and focused | 653 | **9.2** | 13.3 | + +macOS throttles a covered window and Compose's frame clock follows it down. Not a BossTerm +defect, but a measurement trap: it is ~30x larger than any effect being measured, so it does +not look like noise, it looks like a catastrophic product bug. **Every figure below was taken +with the window raised**, asserted per run before the workload starts. An earlier draft of +this file reported 262-917 ms numbers that were entirely this artefact. + +--- + +## Results + +| workload | config | byteToPaint p50 | p95 | paintCost p50 | drawCalls p50 | +|---|---|---|---|---|---| +| interactive | baseline (balanced, 8/50 ms debounce) | 16.4 | 18.4 | 1.15 | 11 | +| interactive | latency mode only | 12.3 | 14.3 | 1.54 | - | +| interactive | **shipped defaults (debounce removed + latency)** | **1.9 - 2.3** | 2.6 - 3.1 | 1.92 | 11 | +| bulk | baseline | 81.9 | 1310.7 | 1.41 | 20 | +| bulk | latency mode only | 196.6 | 1441.8 | 2.56 | - | +| bulk | **shipped defaults** | 491.5 | **983.0** | 4.10 | 128 | +| tui | baseline | 9.2 | 15.4 | 11.26 | 208 | +| tui | **shipped defaults (all on)** | 11.3 | 12.3 | 10.24 | **30** | +| scroll | baseline | 41.0 | 73.7 | 5.63 | 176 | +| scroll | **shipped defaults (all on)** | 45.1 | 98.3 | **2.30** | **60** | + +The `interactive` and `bulk` "shipped defaults" rows are the median of three consecutive +runs each; they were tight (interactive p50 1.9/2.3/2.0, bulk p95 983.0 three times). + +--- + +## What shipped, and what it bought + +**The interactive echo path: 16.4 ms -> ~2.0 ms, an 87% cut.** +Baseline `interactive` was 16.4 ms of which only 1.8 ms was `triggerToPaint`, so ~14.6 ms sat +ahead of the redraw trigger: the 5 ms `BALANCED` poll, the 8 ms debounce, and parse. Removing +both leaves `byteToPaint` essentially equal to `triggerToPaint` (1.9 vs 1.8), which is the +signature of nothing being spent before the trigger. This is the path a user feels while +typing, and it is now bounded by the frame clock rather than by a sleep. + +**Frame counts stayed vsync-capped without the debounce** (~62/sec on `tui`), so the sleep was +not what kept the terminal from over-rendering: the frame clock was, and the CONFLATED +channel plus Compose's own per-frame coalescing already do the job the debounce was added for. + +--- + +## Bulk output: profiled, then fixed (3 changes, ~2.5x) + +Measured as `queueWaitMs` p50/p95, the time a PTY chunk sits in the data-stream queue before +the emulator takes it. That series has n ~5400 per run (one sample per chunk), so it is the +reliable one here; `byteToPaintMs` on this workload sometimes lands only a handful of frames. + +| state | queueWait p50 | p95 | +|---|---|---| +| before | 786 - 1179 | 1572 - 1966 | +| + `isAlive()` cached, redraw sends coalesced | 524 - 655 | 1048 - 1180 | +| + ASCII grapheme fast path | 262 - 459 | 491 - 655 | +| + `visualColToBufferCol` fast path | **147 - 262** | **262 - 360** | + +End to end that is roughly **5x** on the bulk queue wait (786-1179 -> 147-262 ms p50). + +Stack-sampling the emulator thread (`DefaultDispatcher-worker-N`, found by matching +`drainTerminalEmulator` in the stack) through a sustained `cat` loop found three costs, none +of which was visible from reading the code: + +**1. An exception per character (20% of parse time).** `drainTerminalEmulator` loops +`while (shouldContinue())`, and `shouldContinue` is `handle::isAlive` -> +`Process.hasExited()` -> `UnixPtyProcess.exitValue()`, which **throws +`IllegalThreadStateException` whenever the child is alive** - the normal case. Java catches +it internally, so the call site looks free. A 5 MB `cat` built ~5.5 million exceptions, each +with a filled-in stack trace. `isAlive()` now caches for 20 ms and latches death. + +**2. An AWT event per redraw request (20%).** `requestRedraw` does `trySend` on the redraw +channel; when the processor is parked, each send resumes its continuation through the Swing +dispatcher, which means `EventQueue.invokeLater`, an `InvocationEvent`, and an +`AccessController.getContext` native stack walk. The emulator requests a redraw on every +buffer mutation. A pending-flag now skips the send when one is already queued. + +**3. ICU grapheme segmentation on plain ASCII (~27%).** `segmentIntoGraphemes` ran the ICU +`RuleBasedBreakIterator`, a per-cluster substring and a width calculation over text that was +ASCII end to end. Nothing below U+0080 is wide, ambiguous, combining, a surrogate, a ZWJ or a +variation selector, so the answer is decidable without ICU. `GraphemeAsciiFastPathTest` +proves the fast path against the BreakIterator path it replaces, over every printable ASCII +character and a corpus of real terminal output; loosening the guard to admit non-ASCII makes +it fail. + +**4. Column conversion on every line wrap (~10%, all of it from one call site).** +`BossTerminal.wrapLines` calls `visualColToBufferCol(line, terminalWidth, line.length())` - +a walk from column 0 to the full width, with an O(runs) `charAt` inside it - every time a +line wraps, which for output wider than the window is every line. A line that needs no +visual-column mapping holds nothing above U+007F, so buffer column and terminal cell are the +same number and the answer is the identity. `ColumnConversionUtils` now short-circuits on +`line.requiresVisualColumnMapping`, which benefits the renderer's hit-testing too. + +That guard IS the correctness argument, so it is tested against a line carrying DWC markers. +Worth noting how that test was arrived at: the first version asserted only columns where the +identity happens to agree, so it passed against a deliberately broken build. The assertions +that matter are the second cell of each wide character, where the buffer index has to snap +back to the glyph's start rather than land on the DWC marker. + +Still ~150-260 ms, so bulk output is improved rather than solved. What remains on the +emulator thread: `TerminalLine.toBuf` / `merge` (~12% of non-parked time), residual AWT +dispatch (~20%), and `joinTo` / `appendElement` string building (~10%). + +### `TerminalLine.merge`: analysed, deliberately not shipped + +`writeCharacters` rebuilds the ENTIRE line through `toBuf` (a `CharArray` plus a +`TextStyle` array of the full line length) and re-derives every style run, whenever a write +lands anywhere but the end. Lines are NUL-filled to width, so that is most writes. + +The obvious fix is a rope-style entry walk: keep the untouched entries, split only the ones +the write overlaps. It is O(entries) instead of O(lineLength) and was written out - but it +is **not** a safe drop-in, because `collectFromBuffer` coalesces adjacent runs with +reference-equal styles and an entry walk does not. Without matching that, every overwrite +fragments the line a little more, and since `charAt` is O(entries), the result is a +permanently slower line in exchange for a one-off saving. That degradation would not show up +in a five-second benchmark; it would show up in a long session, which is the worst way to +find it. + +Doing it properly needs run coalescing across the splice boundaries, and that deserves its +own change rather than being tacked onto a latency pass. `TerminalLineWriteModelTest` is +committed as the harness for it: a randomised model check that pins what `writeString` must +produce, cell by cell, independently of how the line is stored. + +### A fix that did not work, and why it looked like it would + +Profiling first pointed at `DebugDataCollector`: 59% of execution samples sat in +`captureState` -> `createSnapshot` -> `TerminalLine.copy`, a full deep copy of the whole +buffer on a 100 ms timer, for a debug panel that defaults to off. Gating it changed bulk +latency **not at all**. + +The samples were real; the inference was wrong. That work runs on `Dispatchers.IO` workers, +*parallel* to the parse, and `JavaMonitorEnter` events were zero - so it never blocked the +emulator thread. A whole-JVM profile answers "where is CPU spent", which is not the same +question as "what is the critical path". The fix was kept anyway (it removes 10 full-buffer +deep copies per second per tab of pure waste) but it is an idle-CPU fix, not this one. + +## Correction: the debounce does NOT own the bulk-output tail + +An earlier revision of this file claimed removing the debounce took `bulk` p95 from 1310 ms to +10.2 ms, a ~99% collapse. **That was wrong.** It rested on a single run that returned only 33 +samples, which should have been treated as suspect rather than reported. Three consecutive +runs on the shipped defaults give p95 983.0 ms every time. + +The honest result is a ~25% improvement on the bulk tail (1310 -> 983 ms), not a fix. + +Where the remaining second goes is now unambiguous, because the probe is split at the redraw +trigger: on `bulk`, `triggerToPaint` p50 is 6.7 ms while `byteToPaint` p50 is 491.5 ms. So +~485 ms of it is upstream of the trigger, and with the debounce gone that leaves **queue wait +and parse**. A 5 MB `cat` arrives as ~640 chunks through an 8 KiB read buffer +(`PlatformServices.desktop.kt`), each one allocating a `ByteArray`, a `copyOf`, and a +`String`, before an emulator that pulls them back out one `Char` at a time. + +**So the bulk-output fix is the PTY and parse path, not the renderer and not the debounce.** +That is a different piece of work from anything on this branch. + +--- + +## Also measured, and worth knowing before scoping renderer work + +**Draw-call count is not the dominant paint cost.** Blank batching cut `drawText` calls +208 -> 30 per frame on `tui`, an 86% reduction, while `paintCost` moved only 11.26 -> 10.24 ms. +On `scroll` the same change took draw calls 176 -> 60 and paint cost 5.63 -> 2.30 ms, which is +a better return but still nothing like proportional. + +The consequence for planning: caching `TextLayoutResult`, or dropping to a Skia `TextBlob` +fast path, both attack the slice that run-merging just showed is small. The per-cell scan and +colour-conversion work in the two full-grid passes is the bigger target, and that is where +renderer work should go next. + +**The renderer change was verified by pixel comparison, not by tests.** Blank batching and +the ASCII probe skip fail by producing a wrong *picture*, which no unit test sees. So +`benchmark/latency/unicode-torture.sh` was rendered twice, with the fast path off and on, and +the two window captures diffed: ZWJ families, flags, skin tones, variation selectors, CJK, +powerline glyphs, underlines spanning gaps, bold/italic, inverse, truecolour runs and aligned +columns are pixel-identical apart from subpixel antialiasing (0.31% of pixels, thin glyph +outlines, no positional drift). Column alignment in particular was checked directly, since a +merged run advancing by font metrics rather than cell width would drift progressively along +a line. It does not. + +**Recomposition is not a bottleneck.** `triggerToPaint` covers recomposition, layout and draw; +it is 1.8-13.3 ms and tracks `paintCost` closely. The 2400-line `ProperTerminal` recomposing +per frame had been suspected as a major cost. It is not. + +**The O(scrollback) snapshot is real but small.** `lockedCapture` p50 rises 0.03 -> 1.28 ms +with 10 000 lines of history (`aged`), roughly 40x, confirming the per-frame walk over screen +plus full history. But 1.3 ms of a 16.7 ms frame is ~8%: worth fixing, not worth prioritising. + +--- + +## Reproducing + +```bash +BOSSTERM_FRAME_PROBE=1 ./gradlew :bossterm-app:run --no-daemon +# raise the window, then per workload: +./benchmark/latency/probe.sh reset +./benchmark/latency/workloads.sh +./benchmark/latency/probe.sh show +``` + +Everything measured here shipped as a default; no flags remain. **Raise the window before +every run** or finding 0 will dominate the result. diff --git a/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionUtils.kt b/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionUtils.kt index 12df4b15c..ea603b71a 100644 --- a/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionUtils.kt +++ b/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionUtils.kt @@ -116,6 +116,18 @@ object ColumnConversionUtils { fun visualColToBufferCol(line: TerminalLine, visualCol: Int, width: Int): Int { if (visualCol <= 0) return 0 + // A line that needs no visual-column mapping holds nothing above U+007F: no + // double-width characters, no DWC markers (U+E000), no combining marks, no + // surrogates. Every buffer column is therefore exactly one terminal cell, and the + // answer is the identity, clamped to the line. + // + // The scan below is O(visualCol) with an O(runs) `charAt` inside it, and + // `BossTerminal.wrapLines` calls it with the FULL terminal width every time a line + // wraps - which, for output whose lines exceed the window, is every line. Stack + // sampling the emulator thread through a sustained `cat` put ~10% of its time here, + // all of it from that one call site. + if (!line.requiresVisualColumnMapping) return minOf(visualCol, width) + var currentVisualCol = 0 var col = 0 diff --git a/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/GraphemeUtils.kt b/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/GraphemeUtils.kt index 1c7335a32..b6cb5bfda 100644 --- a/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/GraphemeUtils.kt +++ b/bossterm-core-mpp/src/jvmMain/kotlin/ai/rever/bossterm/terminal/util/GraphemeUtils.kt @@ -168,9 +168,59 @@ object GraphemeUtils { * @param text The string to segment * @return List of grapheme clusters */ + /** + * True when every character is printable ASCII (U+0020..U+007E). + * + * Control characters are excluded deliberately: the emulator routes them separately and + * their width is not simply 1, so letting them into the fast path would be a behaviour + * change rather than an optimisation. + */ + internal fun isAllPrintableAscii(text: String): Boolean { + for (ch in text) { + if (ch.code < 0x20 || ch.code > 0x7E) return false + } + return true + } + + /** Interned single-character clusters for printable ASCII, built once. */ + private val asciiClusters: Array = Array(0x7F - 0x20) { i -> + val ch = (0x20 + i).toChar() + GraphemeCluster(ch.toString(), 1, intArrayOf(ch.code)) + } + + private fun asciiCluster(ch: Char): GraphemeCluster = asciiClusters[ch.code - 0x20] + fun segmentIntoGraphemes(text: String): List { if (text.isEmpty()) return emptyList() + // Printable ASCII cannot form a multi-character grapheme cluster and is always one + // column wide: no combining marks, no ZWJ, no variation selectors, no surrogates, + // nothing wide or ambiguous lives below U+0080. So the ICU BreakIterator, the + // per-cluster substring and the width calculation are all decidable without them. + // + // This is not a marginal case - it is essentially all terminal output. Stack + // sampling the emulator thread through a 5 MB `cat` put ~27% of its time in this + // call chain (`segmentIntoGraphemes` -> `calculateGraphemeWidth` -> + // `extractCodePoints` / `isEmojiPresentation` / `RuleBasedBreakIterator`), for text + // that was ASCII from end to end. + // + // Anything non-ASCII falls through to ICU unchanged; the boundary is one cheap scan. + if (isAllPrintableAscii(text)) { + return ArrayList(text.length).apply { + for (ch in text) add(asciiCluster(ch)) + } + } + + return segmentViaBreakIterator(text) + } + + /** + * The full ICU segmentation, split out so the ASCII fast path above can be proved + * equivalent to it rather than argued to be. + */ + internal fun segmentViaBreakIterator(text: String): List { + if (text.isEmpty()) return emptyList() + val result = mutableListOf() val iterator = breakIterator.get() iterator.setText(text) diff --git a/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/model/TerminalLineWriteModelTest.kt b/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/model/TerminalLineWriteModelTest.kt new file mode 100644 index 000000000..316cf34fe --- /dev/null +++ b/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/model/TerminalLineWriteModelTest.kt @@ -0,0 +1,138 @@ +package ai.rever.bossterm.terminal.model + +import ai.rever.bossterm.terminal.TextStyle +import ai.rever.bossterm.terminal.util.CharUtils +import kotlin.random.Random +import kotlin.test.Test +import kotlin.test.assertEquals + +/** + * A model check on overlapping writes into a [TerminalLine]. + * + * `writeString` into the middle of a line goes through `merge`, which rebuilds the whole + * line into a char array plus a style array and then re-derives the style runs. Any faster + * path for that has to produce the identical line, and "identical" here means every cell's + * character and every cell's style - not a similar-looking entry list. + * + * This validates against an independent model (a plain char array and style array the test + * maintains itself) rather than against the previous implementation, so it pins the + * specification instead of the incumbent behaviour, and it keeps `TextEntries` private. + * + * Randomised with a fixed seed: the interesting cases are overlaps that start and end + * partway through an existing run, and enumerating those by hand reliably misses some. + */ +class TerminalLineWriteModelTest { + + private val styles = listOf( + TextStyle.EMPTY, + TextStyle(null, null, setOf(TextStyle.Option.BOLD)), + TextStyle(null, null, setOf(TextStyle.Option.ITALIC)), + TextStyle(null, null, setOf(TextStyle.Option.UNDERLINED)) + ) + + /** The line as the terminal should see it, maintained independently of TerminalLine. */ + private class Model { + val chars = ArrayList() + val styles = ArrayList() + + fun write(x: Int, text: String, style: TextStyle) { + // A gap is written as NUL, but TextEntries.add un-nullifies it as soon as any + // non-NUL entry lands after it, so it reads back as EMPTY_CHAR. Every case here + // writes text after the gap, so that conversion has always happened. + while (chars.size < x) { + chars.add(CharUtils.EMPTY_CHAR) + styles.add(TextStyle.EMPTY) + } + for (i in text.indices) { + val at = x + i + if (at < chars.size) { + chars[at] = text[i] + styles[at] = style + } else { + chars.add(text[i]) + styles.add(style) + } + } + } + } + + private fun assertMatches(line: TerminalLine, model: Model, note: String) { + assertEquals(model.chars.size, line.length(), "length differs after $note") + for (i in model.chars.indices) { + assertEquals(model.chars[i], line.charAt(i), "char at $i differs after $note") + assertEquals( + model.styles[i], + line.getStyleAt(i) ?: TextStyle.EMPTY, + "style at $i differs after $note" + ) + } + } + + @Test + fun overlappingWritesMatchTheModel() { + val random = Random(20260827) + repeat(200) { case -> + val line = TerminalLine() + val model = Model() + val ops = StringBuilder() + + repeat(6) { + val x = random.nextInt(0, 24) + val len = random.nextInt(1, 12) + val style = styles[random.nextInt(styles.size)] + val text = (0 until len).map { ('a' + random.nextInt(26)) }.joinToString("") + + ops.append("write($x, \"$text\") ") + line.writeString(x, CharBuffer(text), style) + model.write(x, text, style) + } + assertMatches(line, model, "case $case: $ops") + } + } + + @Test + fun aWriteStrictlyInsideAnExistingRunSplitsItCorrectly() { + // The case a faster merge is most likely to get wrong: the overwrite starts and + // ends partway through one run, so the run has to become head + new + tail. + val line = TerminalLine() + val model = Model() + line.writeString(0, CharBuffer("aaaaaaaaaa"), styles[0]) + model.write(0, "aaaaaaaaaa", styles[0]) + line.writeString(3, CharBuffer("XY"), styles[1]) + model.write(3, "XY", styles[1]) + assertMatches(line, model, "inner split") + } + + @Test + fun aWriteExtendingPastTheEndKeepsTheTail() { + val line = TerminalLine() + val model = Model() + line.writeString(0, CharBuffer("abcde"), styles[0]) + model.write(0, "abcde", styles[0]) + line.writeString(3, CharBuffer("ZZZZ"), styles[2]) + model.write(3, "ZZZZ", styles[2]) + assertMatches(line, model, "write past end") + } + + @Test + fun aWritePastTheEndFillsTheGap() { + val line = TerminalLine() + val model = Model() + line.writeString(0, CharBuffer("ab"), styles[0]) + model.write(0, "ab", styles[0]) + line.writeString(6, CharBuffer("Q"), styles[1]) + model.write(6, "Q", styles[1]) + assertMatches(line, model, "gap fill") + } + + @Test + fun awholeLineOverwriteReplacesEverything() { + val line = TerminalLine() + val model = Model() + line.writeString(0, CharBuffer("abcdef"), styles[0]) + model.write(0, "abcdef", styles[0]) + line.writeString(0, CharBuffer("ABCDEF"), styles[3]) + model.write(0, "ABCDEF", styles[3]) + assertMatches(line, model, "full overwrite") + } +} diff --git a/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionFastPathTest.kt b/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionFastPathTest.kt new file mode 100644 index 000000000..7dd5d946a --- /dev/null +++ b/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/util/ColumnConversionFastPathTest.kt @@ -0,0 +1,83 @@ +package ai.rever.bossterm.terminal.util + +import ai.rever.bossterm.terminal.TextStyle +import ai.rever.bossterm.terminal.model.CharBuffer +import ai.rever.bossterm.terminal.model.TerminalLine +import kotlin.test.Test +import kotlin.test.assertEquals + +/** + * `visualColToBufferCol` short-circuits to the identity for lines that need no + * visual-column mapping. That is sound only because such a line holds nothing above + * U+007F: no double-width character, no DWC marker (U+E000), no combining mark, no + * surrogate. Every buffer column is then exactly one terminal cell. + * + * The guard is the whole correctness argument, so it is tested here rather than assumed. + * Without these, removing the guard entirely - taking the fast path for every line - passed + * the whole suite, which is exactly the silent breakage that matters: columns would be + * mapped as if wide characters were one cell wide, so selections, mouse hit-testing and + * line-wrap truncation would all land on the wrong cell whenever CJK or emoji is on screen. + */ +class ColumnConversionFastPathTest { + + private val style = TextStyle.EMPTY + + private fun asciiLine(text: String) = TerminalLine().apply { + writeString(0, CharBuffer(text), style) + } + + /** A line where each wide char occupies two cells: the char then a DWC marker. */ + private fun wideLine(): TerminalLine { + val sb = StringBuilder() + // "ab" then two double-width CJK characters, each followed by its DWC spacer. + sb.append("ab") + sb.append('你').append(CharUtils.DWC) + sb.append('好').append(CharUtils.DWC) + sb.append("cd") + return TerminalLine().apply { writeString(0, CharBuffer(sb.toString()), style) } + } + + @Test + fun plainAsciiMapsAsTheIdentity() { + val line = asciiLine("hello world") + val width = line.length() + for (v in 0..width) { + assertEquals(minOf(v, width), ColumnConversionUtils.visualColToBufferCol(line, v, width)) + } + } + + @Test + fun wideCharactersDoNotMapAsTheIdentity() { + // The assertion that kills a missing guard: visual column 4 sits inside the CJK + // run, whose buffer index is further along because each wide char carries a DWC + // spacer. If the fast path were taken here, this would come back as 4. + val line = wideLine() + val width = line.length() + + // buffer: 0=a 1=b 2=你 3=DWC 4=好 5=DWC 6=c 7=d + // visual: 0=a 1=b 2..3=你 4..5=好 6=c 7=d + // + // Most columns agree with the identity by coincidence. The ones that do NOT are the + // second cell of each wide character, where the visual column points into the glyph + // and the buffer index must snap back to its start - landing on the DWC marker + // instead is precisely what a missing guard would do. + assertEquals( + 2, ColumnConversionUtils.visualColToBufferCol(line, 3, width), + "visual col 3 is the second cell of the first wide char: it must snap back to " + + "buffer 2, not land on the DWC marker at buffer 3" + ) + assertEquals( + 4, ColumnConversionUtils.visualColToBufferCol(line, 5, width), + "visual col 5 is the second cell of the second wide char: it must snap back to " + + "buffer 4, not land on the DWC marker at buffer 5" + ) + } + + @Test + fun theGuardRejectsAWideLineAndAcceptsAnAsciiOne() { + // Direct check on the predicate the fast path keys off, so a change to how + // `requiresVisualColumnMapping` is maintained cannot silently widen the fast path. + assertEquals(false, asciiLine("plain ascii").requiresVisualColumnMapping) + assertEquals(true, wideLine().requiresVisualColumnMapping) + } +} diff --git a/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/util/GraphemeAsciiFastPathTest.kt b/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/util/GraphemeAsciiFastPathTest.kt new file mode 100644 index 000000000..48070b78d --- /dev/null +++ b/bossterm-core-mpp/src/jvmTest/kotlin/ai/rever/bossterm/terminal/util/GraphemeAsciiFastPathTest.kt @@ -0,0 +1,90 @@ +package ai.rever.bossterm.terminal.util + +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertFalse +import kotlin.test.assertTrue + +/** + * `segmentIntoGraphemes` skips ICU entirely for printable ASCII, which is essentially all + * terminal output. The claim is that ICU cannot disagree there: nothing below U+0080 is + * wide, ambiguous, combining, a surrogate, a ZWJ or a variation selector. + * + * That claim is checkable rather than arguable, so it is checked here - against the very + * BreakIterator path it replaces, over every printable ASCII character and a corpus of real + * terminal output. + */ +class GraphemeAsciiFastPathTest { + + private fun assertSameSegmentation(text: String) { + val fast = GraphemeUtils.segmentIntoGraphemes(text) + val icu = GraphemeUtils.segmentViaBreakIterator(text) + assertEquals(icu.size, fast.size, "cluster count differs for " + text.take(40)) + for (i in icu.indices) { + assertEquals(icu[i].text, fast[i].text, "cluster $i text differs") + assertEquals(icu[i].visualWidth, fast[i].visualWidth, "cluster $i width differs") + assertTrue( + icu[i].codePoints.contentEquals(fast[i].codePoints), + "cluster $i code points differ" + ) + } + } + + @Test + fun everyPrintableAsciiCharacterSegmentsIdentically() { + for (code in 0x20..0x7E) { + assertSameSegmentation(code.toChar().toString()) + } + } + + @Test + fun realTerminalOutputSegmentsIdentically() { + listOf( + "the quick brown fox jumps over the lazy dog 0123456789", + "drwxr-xr-x 12 user staff 384 Aug 26 10:11 src", + " INFO module-07 request completed in 42 ms path=/api/v1/x/9", + "a b c d e", + "!\"#\$%&'()*+,-./:;<=>?@[\\]^_`{|}~" + ).forEach(::assertSameSegmentation) + } + + @Test + fun nonAsciiStillGoesThroughIcu() { + // The guard must reject anything ICU could segment differently, or the fast path + // would flatten a family emoji into several one-column clusters. + listOf( + "👨‍💻", // ZWJ: man technologist + "🇺🇸", // regional indicators: flag + "👋🏽", // skin tone modifier + "✔️", // variation selector + "你好", // CJK + "é", // combining acute + "ascii then 你" // mixed + ).forEach { text -> + assertFalse( + GraphemeUtils.isAllPrintableAscii(text), + "guard must not claim this is plain ASCII" + ) + assertSameSegmentation(text) + } + } + + @Test + fun controlCharactersAreNotTakenByTheFastPath() { + // Their width is not simply 1, so admitting them would be a behaviour change + // rather than an optimisation. + assertFalse(GraphemeUtils.isAllPrintableAscii("a\tb")) + assertFalse(GraphemeUtils.isAllPrintableAscii("a\nb")) + assertFalse(GraphemeUtils.isAllPrintableAscii("a\u0000b")) + assertFalse(GraphemeUtils.isAllPrintableAscii("a\u007Fb")) + // A plain space, by contrast, IS printable ASCII and must stay on the fast + // path - it is the most common character in terminal output. + assertTrue(GraphemeUtils.isAllPrintableAscii("a b")) + } + + @Test + fun theFastPathActuallyEngages() { + // A guard that never fires would pass every check above while changing nothing. + assertTrue(GraphemeUtils.isAllPrintableAscii("plain ascii line 123")) + } +} diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ComposeTerminalDisplay.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ComposeTerminalDisplay.kt index d5de559b4..9ffbba1ac 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ComposeTerminalDisplay.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ComposeTerminalDisplay.kt @@ -1,5 +1,6 @@ package ai.rever.bossterm.compose +import ai.rever.bossterm.compose.rendering.FrameLatencyProbe import androidx.compose.runtime.mutableStateOf import androidx.compose.runtime.State import ai.rever.bossterm.core.util.TermSize @@ -17,37 +18,39 @@ import kotlinx.coroutines.flow.asStateFlow import java.util.concurrent.atomic.AtomicReference /** - * Compose implementation of TerminalDisplay interface with adaptive debouncing. + * Compose implementation of TerminalDisplay. * - * Phase 2 Optimization: Automatically switches between three rendering modes - * based on output rate to reduce redraws by 51-91% for medium/large files - * while maintaining zero latency for interactive use. + * Redraws are coalesced by the CONFLATED [redrawChannel] and, downstream of it, by Compose + * itself: many writes to [_redrawTrigger] between two frames collapse into one + * recomposition. Nothing here waits on a clock. + * + * It used to. An adaptive debounce slept 8 ms per redraw, and 50 ms once output passed 100 + * redraws/sec, to cut redraw COUNT on large files. Measured against the thing a user + * actually feels, that trade was bad: an isolated keystroke echo took 16.4 ms, of which only + * 1.8 ms was downstream of the redraw trigger. Removing the wait (with the data stream's own + * poll, see TerminalSettings.performanceMode) takes it to ~2.0 ms, and `byteToPaint` then + * equals `triggerToPaint`, which is the signature of nothing being spent before the trigger. + * + * Frame counts stay vsync-capped (~62/sec) without it, so the sleep was never what kept the + * terminal from over-rendering: the frame clock was, and the CONFLATED channel plus Compose's + * per-frame coalescing already do the job this was added for. + * + * What it does NOT fix is bulk output: a 5 MB `cat` still shows a ~983 ms p95, down only + * ~25% from 1310 ms, and on that workload `triggerToPaint` is 6.7 ms against a `byteToPaint` + * of 491 ms. That ~485 ms is queue wait and parse, upstream of anything here. + * + * See `benchmark_results/LATENCY_BASELINE_2026-08-27.md`. */ class ComposeTerminalDisplay : TerminalDisplay { - // ===== ADAPTIVE DEBOUNCING (Phase 2) ===== /** - * Rendering modes that adapt to output rate. - */ - enum class RedrawMode(val debounceMs: Long, val description: String) { - INTERACTIVE(8L, "120fps equivalent for responsive typing"), - HIGH_VOLUME(50L, "20fps for bulk output, triggered at >100 redraws/sec"), - IMMEDIATE(0L, "Instant for keyboard/mouse input") - } - - /** - * Redraw request with priority. + * Redraw request. Carries no priority any more: with the debounce gone, an "immediate" + * and a "normal" request do exactly the same thing. */ data class RedrawRequest( val timestamp: Long = System.currentTimeMillis(), - val priority: RedrawPriority = RedrawPriority.NORMAL ) - enum class RedrawPriority { - IMMEDIATE, // User input - bypass debounce - NORMAL // PTY output - apply debounce - } - /** * The four cursor fields as ONE value. * @@ -63,24 +66,28 @@ class ComposeTerminalDisplay : TerminalDisplay { val shape: CursorShape?, ) - // Current rendering mode - @Volatile - private var currentMode = RedrawMode.INTERACTIVE - // Channel for queuing redraw requests with conflation private val redrawChannel = Channel(Channel.CONFLATED) + /** + * Whether a redraw is already queued and unclaimed. + * + * The channel is CONFLATED, so a second `trySend` is harmless to correctness - but it + * is NOT free. When the processor is parked on the channel, each send resumes its + * continuation through the Swing dispatcher, and that means `EventQueue.invokeLater`, + * an `InvocationEvent`, and an `AccessController.getContext` stack walk, per call. The + * emulator requests a redraw on every buffer mutation, so bulk output turned that into + * an AWT event storm: stack-sampling the parse thread under load put 20% of its time + * in `AWTEvent.` beneath `requestRedraw`. + * + * Cleared by the processor BEFORE it redraws, so a mutation that lands during a redraw + * still schedules the next one. + */ + private val redrawQueued = java.util.concurrent.atomic.AtomicBoolean(false) + // Coroutine scope for redraw processing private val redrawScope = CoroutineScope(Dispatchers.Main + SupervisorJob()) - // Timestamp tracking for burst detection - private val recentRedraws = ArrayDeque(100) - private val redrawTimestampsLock = Any() - - // Mode transition tracking - private var lastModeSwitch = System.currentTimeMillis() - private var returnToInteractiveJob: Job? = null - init { // Start redraw processor coroutine startRedrawProcessor() @@ -249,18 +256,7 @@ class ComposeTerminalDisplay : TerminalDisplay { override fun scrollArea(scrollRegionTop: Int, scrollRegionSize: Int, dy: Int) { // Note: This method is only called for actual scrolling operations (cursor past bottom, etc.) // Regular text output is handled by the ModelListener registered on TerminalTextBuffer - // Smart priority detection: Use IMMEDIATE for interactive use, NORMAL for bulk output - val isHighVolume = synchronized(redrawTimestampsLock) { - currentMode == RedrawMode.HIGH_VOLUME - } - - if (isHighVolume) { - // Bulk output detected (cat, streaming) - use debouncing for 98% reduction - requestRedraw() - } else { - // Interactive use (typing, prompts) - instant response for best UX - requestImmediateRedraw() - } + requestRedraw() } override fun useAlternateScreenBuffer(useAlternateScreenBuffer: Boolean) { @@ -340,36 +336,20 @@ class ComposeTerminalDisplay : TerminalDisplay { try { for (request in redrawChannel) { + // Released before the redraw, not after, so a buffer mutation that + // lands mid-redraw still queues the next frame. + redrawQueued.set(false) try { - when (request.priority) { - RedrawPriority.IMMEDIATE -> { - // Re-check sync mode: a ?2026h may have arrived after this - // redraw was queued (e.g., rapid ?2026l/?2026h toggle by CLIs - // like "claude" that use synchronized output for spinner frames). - synchronized(syncUpdateLock) { - if (_synchronizedUpdateEnabled) { - _pendingRedrawDuringSync = true - null - } else Unit - } ?: continue - actualRedraw() - } - - RedrawPriority.NORMAL -> { - val mode = detectAndUpdateMode() - delay(mode.debounceMs) - - // Re-check sync mode after debounce delay: a new ?2026h may - // have been processed by the emulator while we were waiting. - synchronized(syncUpdateLock) { - if (_synchronizedUpdateEnabled) { - _pendingRedrawDuringSync = true - null - } else Unit - } ?: continue - actualRedraw() - } - } + // Re-check sync mode: a ?2026h may have arrived after this + // redraw was queued (e.g., rapid ?2026l/?2026h toggle by CLIs + // like "claude" that use synchronized output for spinner frames). + synchronized(syncUpdateLock) { + if (_synchronizedUpdateEnabled) { + _pendingRedrawDuringSync = true + null + } else Unit + } ?: continue + actualRedraw() } catch (e: Exception) { // Log but don't crash the loop - individual redraw failures // should not kill the entire rendering pipeline @@ -391,61 +371,6 @@ class ComposeTerminalDisplay : TerminalDisplay { } } - /** - * Detect current redraw rate and update mode accordingly. - * Switches to HIGH_VOLUME when >100 redraws/sec detected. - */ - private fun detectAndUpdateMode(): RedrawMode { - val now = System.currentTimeMillis() - - synchronized(redrawTimestampsLock) { - // Add current timestamp - recentRedraws.addLast(now) - - // Remove timestamps older than 1 second - while (recentRedraws.isNotEmpty() && - now - recentRedraws.first() > 1000) { - recentRedraws.removeFirst() - } - - // Calculate redraws per second - val rate = recentRedraws.size - - // Determine appropriate mode - val newMode = when { - rate > 100 -> RedrawMode.HIGH_VOLUME // Bulk output detected - else -> RedrawMode.INTERACTIVE // Normal interactive use - } - - // Handle mode transition - if (newMode != currentMode && newMode != RedrawMode.IMMEDIATE) { - onModeTransition(currentMode, newMode) - currentMode = newMode - lastModeSwitch = now - } - - return currentMode - } - } - - /** - * Handle transitions between rendering modes. - */ - private fun onModeTransition(from: RedrawMode, to: RedrawMode) { - // Schedule automatic return to INTERACTIVE after bulk output stops - if (to == RedrawMode.HIGH_VOLUME) { - returnToInteractiveJob?.cancel() - returnToInteractiveJob = redrawScope.launch { - delay(500) // Wait 500ms of low activity - synchronized(redrawTimestampsLock) { - if (recentRedraws.size < 50) { // Less than 50 redraws/sec - currentMode = RedrawMode.INTERACTIVE - } - } - } - } - } - /** * Trigger a redraw of the terminal (normal priority, applies debouncing). */ @@ -459,9 +384,14 @@ class ComposeTerminalDisplay : TerminalDisplay { } } - // Conflated channel: a full channel simply coalesces this request into the - // pending one, which is the intended debouncing behaviour. - redrawChannel.trySend(RedrawRequest(priority = RedrawPriority.NORMAL)) + // Skip the send entirely when one is already pending: see [redrawQueued]. + if (redrawQueued.compareAndSet(false, true)) { + // Release the claim if the send did not land, or a closed channel would latch + // the flag and silently stop every future redraw. + if (redrawChannel.trySend(RedrawRequest()).isFailure) { + redrawQueued.set(false) + } + } } /** @@ -564,22 +494,13 @@ class ComposeTerminalDisplay : TerminalDisplay { } actualRedraw() } - - // Reset to INTERACTIVE mode after brief delay - redrawScope.launch { - delay(100) - synchronized(redrawTimestampsLock) { - if (currentMode != RedrawMode.HIGH_VOLUME) { - currentMode = RedrawMode.INTERACTIVE - } - } - } } /** * Perform the actual redraw by updating Compose state. */ private fun actualRedraw() { + FrameLatencyProbe.markRedrawTriggered() _redrawTrigger.value += 1 } @@ -594,7 +515,6 @@ class ComposeTerminalDisplay : TerminalDisplay { * and closing an already-closed channel are both no-ops. */ fun dispose() { - returnToInteractiveJob?.cancel() redrawJob?.cancel() redrawScope.cancel() redrawChannel.close() diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/PlatformServices.desktop.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/PlatformServices.desktop.kt index 5511f27dd..1bb5a3e6b 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/PlatformServices.desktop.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/PlatformServices.desktop.kt @@ -168,6 +168,11 @@ class DesktopProcessService( */ private val isShuttingDown = java.util.concurrent.atomic.AtomicBoolean(false) + private companion object { + /** 20 ms: far longer than a parse step, far shorter than a human notices. */ + const val ALIVE_CACHE_NANOS = 20_000_000L + } + override suspend fun write(data: String) { outputStream.write(data.toByteArray()) outputStream.flush() @@ -269,7 +274,41 @@ class DesktopProcessService( return bytes.size } - override fun isAlive(): Boolean = process.isAlive + /** + * Liveness, cached for [ALIVE_CACHE_NANOS]. + * + * `Process.isAlive()` calls `hasExited()`, which on pty4j calls + * `UnixPtyProcess.exitValue()` and lets it THROW `IllegalThreadStateException` + * whenever the child is still running - the normal case. Java catches it, so the + * cost is invisible at the call site: a full exception with a filled-in stack + * trace, every call. + * + * The emulator drain loop calls this once per CHARACTER + * (`drainTerminalEmulator`'s `while (shouldContinue())`), so a 5 MB `cat` built + * ~5.5 million exceptions. Stack-sampling the parse thread under load put 20% of + * its time in `Throwable.fillInStackTrace` beneath this call. + * + * A short TTL is safe here because nothing depends on sub-millisecond precision: + * the drain loop's real termination signal is EOF from the data stream, which the + * PTY reader closes when the child goes away. This check is the belt-and-braces + * one. Death is also latched - a process that has exited never comes back, so a + * false result is cached forever and never pays the syscall again. + */ + override fun isAlive(): Boolean { + if (knownDead) return false + val now = System.nanoTime() + val checked = aliveCheckedAtNanos + if (checked != 0L && now - checked < ALIVE_CACHE_NANOS) return cachedAlive + val alive = process.isAlive + cachedAlive = alive + aliveCheckedAtNanos = now + if (!alive) knownDead = true + return alive + } + + @Volatile private var cachedAlive: Boolean = true + @Volatile private var aliveCheckedAtNanos: Long = 0L + @Volatile private var knownDead: Boolean = false override suspend fun kill() { // Signal shutdown to prevent race conditions with read() diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollector.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollector.kt index 6bf9a19ac..14aa6211e 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollector.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollector.kt @@ -39,6 +39,28 @@ class DebugDataCollector( private val snapshots = ConcurrentLinkedQueue() private val chunkIndex = AtomicInteger(0) + /** + * Sizes of [chunks] and [snapshots], tracked rather than asked for. + * + * `ConcurrentLinkedQueue.size()` is O(n): it walks the list. Both ring buffers trimmed + * with `while (queue.size > max) queue.poll()`, so every chunk that crossed the tty paid + * an O(maxChunks) scan - 1000 node traversals per chunk, on the PTY reader thread. + */ + private val chunkCount = AtomicInteger(0) + private val snapshotCount = AtomicInteger(0) + + /** Drop entries until [count] is back within [max]. */ + private fun trim(queue: ConcurrentLinkedQueue, count: AtomicInteger, max: Int) { + while (count.get() > max) { + if (queue.poll() == null) { + // Someone else drained it; do not let the counter drift below the queue. + count.set(queue.size) + return + } + count.decrementAndGet() + } + } + @Volatile private var enabled = true @@ -66,16 +88,29 @@ class DebugDataCollector( ) chunks.offer(chunk) - - // Trim to maxChunks (circular buffer) - while (chunks.size > maxChunks) { - chunks.poll() - } + chunkCount.incrementAndGet() + trim(chunks, chunkCount, maxChunks) // Write to file log if active writeChunkToFile(chunk) } + /** + * Whether a state snapshot is worth taking. + * + * TerminalTab carries TWO debug flags and they mean different things: + * + * - `debugEnabled` is background COLLECTION, seeded from `settings.debugModeEnabled`. + * - `debugPanelVisible` is the UI, toggled with Cmd/Ctrl+Shift+D. + * + * Either one means somebody wants the data, so either one must capture. Reading only + * the first is a real bug that shipped for one commit: pressing Cmd+Shift+D showed an + * empty panel, because opening the panel does not set the collection flag. It is a pure + * function so that mistake is testable rather than only visible by hand. + */ + internal fun shouldCaptureState(collectionEnabled: Boolean, panelVisible: Boolean): Boolean = + collectionEnabled || panelVisible + /** * Capture a snapshot of the current terminal state. * @@ -88,6 +123,18 @@ class DebugDataCollector( val currentTab = tab ?: return // Skip if tab not set yet + // Nobody is looking: skip the snapshot entirely. + // + // This is not a micro-optimisation. `createSnapshot()` is the FULL deep copy - every + // line in the buffer, screen and history, cloned - and this runs on a timer every + // `debugCaptureInterval` (100 ms) for the life of every tab. With debug off, which + // is the default, all of it was thrown away. Profiling a 5 MB `cat` put 59% of + // samples in this call chain. + // + // The loop keeps ticking rather than being torn down, because the panel can be + // toggled at any time (Cmd/Ctrl+Shift+D) and must start showing data immediately. + if (!shouldCaptureState(currentTab.debugEnabled.value, currentTab.debugPanelVisible.value)) return + try { val textBuffer = currentTab.textBuffer val terminal = currentTab.terminal @@ -133,11 +180,8 @@ class DebugDataCollector( ) snapshots.offer(snapshot) - - // Trim to maxSnapshots (circular buffer) - while (snapshots.size > maxSnapshots) { - snapshots.poll() - } + snapshotCount.incrementAndGet() + trim(snapshots, snapshotCount, maxSnapshots) } catch (e: Exception) { println("WARN: Failed to capture terminal state: ${e.message}") @@ -232,6 +276,10 @@ class DebugDataCollector( fun clear() { chunks.clear() snapshots.clear() + // Counters shadow the queues; clearing one without the other would make trim() + // evict live entries forever. + chunkCount.set(0) + snapshotCount.set(0) chunkIndex.set(0) } diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/FrameLatencyProbe.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/FrameLatencyProbe.kt new file mode 100644 index 000000000..2334f1de4 --- /dev/null +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/FrameLatencyProbe.kt @@ -0,0 +1,373 @@ +package ai.rever.bossterm.compose.rendering + +import java.io.File +import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicLong +import java.util.concurrent.atomic.AtomicLongArray + +/** + * Opt-in glass-to-pixel latency instrumentation, gated on `BOSSTERM_FRAME_PROBE=1`. + * + * The existing `benchmark/` suite measures how fast the emulator *consumes* bytes - it + * cannot see the time between a byte landing in the PTY and the pixel that byte produces. + * That interval is where the redraw debounce, the data-stream poll timeout and the paint + * cost all live, so it needs its own measurement before any of them are touched. + * + * What each series means: + * + * - [byteToPaint] - a PTY chunk's arrival (stamped in `BlockingTerminalDataStream.append`, + * before the queue wait) to the end of the paint pass that first draws it. This is the + * number a user feels. It is *draw-issued*, not photons: it excludes GPU present and + * vsync, so it is a lower bound on real latency and must be anchored against an external + * capture before any conclusion rests on the absolute value. Deltas between two builds + * measured the same way are sound regardless. + * - [paintCost] - wall time inside `renderTerminal`. The number that decides whether a + * throttle is needed at all. + * - [snapshotCost] - wall time the UI thread spends holding the terminal buffer lock to + * capture a frame. Expected to scale with scrollback depth, which is the shape that + * makes a long-lived session feel worse than a fresh one. + * - [drawCallsPerFrame] - `drawText` invocations per paint. The multiplier on text layout. + * + * All recording happens on the UI thread (the paint pass); [markArrival] is the one method + * called from the PTY/emulator threads and only performs a CAS. + * + * When disabled, every method here is an `enabled` check and a return, and no timestamps + * are taken. Nothing in this file allocates on the hot path. + */ +object FrameLatencyProbe { + + const val ENV_FLAG: String = "BOSSTERM_FRAME_PROBE" + + /** Sentinel for "no un-rendered chunk is pending". */ + private const val NONE = Long.MIN_VALUE + + /** + * Whether any measurement happens at all. + * + * Seeded from the environment and settable only from this module, so tests can exercise + * the recording paths without a process-wide env var. Nothing in production flips it: + * the sampler thread is started from `init` against the env-derived value, so a later + * write enables recording but never spawns a writer. + */ + @Volatile + var enabled: Boolean = System.getenv(ENV_FLAG).let { it == "1" || it.equals("true", ignoreCase = true) } + internal set + + /** + * Arrival time of the oldest PTY chunk not yet drawn, or [NONE]. + * + * Only the *oldest* is kept: a paint draws the whole buffer, so a frame that renders + * chunk N also renders every chunk before it, and the latency that matters is the one + * the earliest byte experienced. Later arrivals inside the same frame lose the CAS and + * are deliberately dropped rather than overwriting an older, worse sample. + */ + private val pendingArrival = AtomicLong(NONE) + + /** Oldest redraw trigger not yet painted, or [NONE]. Same earliest-wins rule as arrival. */ + private val pendingTrigger = AtomicLong(NONE) + + /** Reset per paint by [beginFrame], read by [endFrame]. */ + private val drawCalls = AtomicInteger(0) + + val byteToPaint: Histogram = Histogram() + + /** + * Redraw trigger to paint: the recomposition and layout window. + * + * [byteToPaint] alone cannot say WHERE the time goes. This splits it: everything up to + * `actualRedraw` (queue wait, parse, debounce) versus everything after it (recomposing + * the composable, layout, then the draw). Without the split, a slow recomposition and a + * long debounce are indistinguishable, and they have opposite fixes. + */ + val triggerToPaint: Histogram = Histogram() + + /** + * How long a PTY chunk sat in the data-stream queue before the emulator took it. + * + * Recorded per chunk, not per paint: this is the one series that says whether bulk + * output is slow because the parser cannot keep up (queue backs up) or because + * something downstream of the parse is stalling. Those have completely different fixes. + */ + val queueWait: Histogram = Histogram() + + /** Total bytes' worth of chunks dequeued, so a sustained parse rate can be derived. */ + private val chunksDequeued = AtomicLong(0) + private val charsDequeued = AtomicLong(0) + val paintCost: Histogram = Histogram() + val snapshotCost: Histogram = Histogram() + val drawCallsPerFrame: Histogram = Histogram() + + /** Paints that drew no newly-arrived data (blink, resize, selection, scroll). */ + private val idleFrames = AtomicLong(0) + + private val startedAtNanos = System.nanoTime() + + /** + * Where the sampler writes. Overridable so two builds can be measured into separate + * files in one scripted run. + */ + private val outFile: File = + File(System.getenv("BOSSTERM_FRAME_PROBE_OUT") ?: "${System.getProperty("user.home")}/.bossterm/frame-probe.json") + + /** + * Touch this file to zero the histograms before a workload; the sampler consumes and + * deletes it. A file rather than a signal or an MCP tool because the probe must add no + * product surface: nothing here is reachable, or even constructed, without the env flag. + */ + private val resetFile: File = File(outFile.absoluteFile.parentFile, "frame-probe.reset") + + init { + if (enabled) startSampler() + } + + private fun startSampler() { + Runtime.getRuntime().addShutdownHook(Thread({ writeSnapshotQuietly() }, "frame-probe-final")) + Thread({ + while (true) { + try { + Thread.sleep(SAMPLE_INTERVAL_MS) + if (resetFile.exists()) { + resetFile.delete() + reset() + } + writeSnapshotQuietly() + } catch (_: InterruptedException) { + return@Thread + } catch (_: Throwable) { + // A diagnostic must never take the app down. Keep sampling. + } + } + }, "frame-probe-sampler").apply { isDaemon = true }.start() + } + + private fun writeSnapshotQuietly() { + runCatching { + val dir = outFile.absoluteFile.parentFile + dir?.mkdirs() + val tmp = File(dir, outFile.name + ".tmp") + tmp.writeText(json()) + // Atomic rename so a reader never sees a half-written file. + if (!tmp.renameTo(outFile)) { + outFile.writeText(json()) + tmp.delete() + } + } + } + + /** Machine-readable snapshot. Latencies in milliseconds. */ + fun json(): String = buildString { + append("{\n") + append(" \"enabled\": ").append(enabled).append(",\n") + append(" \"uptimeSeconds\": ") + .append(String.format(java.util.Locale.ROOT, "%.1f", (System.nanoTime() - startedAtNanos) / 1e9)) + .append(",\n") + append(" \"byteToPaintMs\": ").append(byteToPaint.jsonMillis()).append(",\n") + append(" \"triggerToPaintMs\": ").append(triggerToPaint.jsonMillis()).append(",\n") + append(" \"queueWaitMs\": ").append(queueWait.jsonMillis()).append(",\n") + append(" \"chunksDequeued\": ").append(chunksDequeued.get()).append(",\n") + append(" \"charsDequeued\": ").append(charsDequeued.get()).append(",\n") + append(" \"paintCostMs\": ").append(paintCost.jsonMillis()).append(",\n") + append(" \"lockedCaptureMs\": ").append(snapshotCost.jsonMillis()).append(",\n") + append(" \"drawCallsPerFrame\": ").append(drawCallsPerFrame.jsonRaw()).append(",\n") + append(" \"idleFrames\": ").append(idleFrames.get()).append("\n") + append("}\n") + } + + private const val SAMPLE_INTERVAL_MS = 1_000L + + /** + * Stamp a PTY chunk's arrival. Called from the data stream the moment a chunk is + * handed over, ahead of the queue wait, so the poll timeout is inside the measurement + * rather than hidden before it. + */ + fun markArrival(nanos: Long) { + if (!enabled) return + // Keep the earliest pending arrival; a later chunk must not reset the clock. + pendingArrival.compareAndSet(NONE, nanos) + } + + /** A chunk of [length] chars left the queue after waiting since [arrivalNanos]. */ + fun markDequeued(arrivalNanos: Long, length: Int) { + if (!enabled) return + queueWait.recordNanos(System.nanoTime() - arrivalNanos) + chunksDequeued.incrementAndGet() + charsDequeued.addAndGet(length.toLong()) + } + + /** Timestamp for a later `record*` call, or 0 when the probe is off. */ + fun startTiming(): Long = if (enabled) System.nanoTime() else 0L + + /** `actualRedraw` bumped the Compose state that will cause the next recomposition. */ + fun markRedrawTriggered() { + if (!enabled) return + pendingTrigger.compareAndSet(NONE, System.nanoTime()) + } + + /** Start of a paint pass. Returns the start timestamp to hand back to [endFrame]. */ + fun beginFrame(): Long { + if (!enabled) return 0L + drawCalls.set(0) + return System.nanoTime() + } + + /** End of a paint pass. [startNanos] is whatever [beginFrame] returned. */ + fun endFrame(startNanos: Long) { + if (!enabled) return + val now = System.nanoTime() + paintCost.recordNanos(now - startNanos) + drawCallsPerFrame.record(drawCalls.get().toLong()) + val trigger = pendingTrigger.getAndSet(NONE) + if (trigger != NONE) triggerToPaint.recordNanos(now - trigger) + val arrival = pendingArrival.getAndSet(NONE) + if (arrival == NONE) idleFrames.incrementAndGet() else byteToPaint.recordNanos(now - arrival) + } + + /** + * Wall time the UI thread spent holding the terminal buffer lock to capture a frame. + * + * The whole locked region, not just `createIncrementalSnapshot`, because the cost that + * matters is how long the emulator is blocked - and it is the same region either way. + */ + fun recordSnapshot(startNanos: Long) { + if (!enabled) return + snapshotCost.recordNanos(System.nanoTime() - startNanos) + } + + /** One `drawText` issued by the current paint. */ + fun countDrawCall() { + if (!enabled) return + drawCalls.incrementAndGet() + } + + /** Drop every sample. Call between workloads so runs do not contaminate each other. */ + fun reset() { + byteToPaint.reset() + triggerToPaint.reset() + queueWait.reset() + chunksDequeued.set(0) + charsDequeued.set(0) + paintCost.reset() + snapshotCost.reset() + drawCallsPerFrame.reset() + idleFrames.set(0) + pendingArrival.set(NONE) + pendingTrigger.set(NONE) + drawCalls.set(0) + } + + /** Human-readable report. Latencies in milliseconds, draw calls as raw counts. */ + fun report(): String = buildString { + appendLine("BossTerm frame probe (enabled=$enabled)") + if (!enabled) { + appendLine(" Set $ENV_FLAG=1 before launching to collect samples.") + return@buildString + } + appendLine(" byte->paint ${byteToPaint.summaryMillis()}") + appendLine(" paint cost ${paintCost.summaryMillis()}") + appendLine(" snapshot cost ${snapshotCost.summaryMillis()}") + appendLine(" drawText/frame ${drawCallsPerFrame.summaryRaw()}") + appendLine(" frames with no new data: ${idleFrames.get()}") + appendLine(" NOTE: byte->paint is draw-issued, excluding GPU present and vsync.") + } + + /** + * Fixed-bucket log histogram: eight sub-buckets per octave, so a reported value is + * never more than 1/8 below the true one. (Four sub-buckets would be 1/4, since the + * widest bucket relative to its own floor is the first in an octave: width 2^k/N at + * value 2^k.) Chosen over storing raw samples because recording sits in the paint + * pass - it must not allocate, and must not grow without bound over a long soak. + * + * Quantiles report the bucket FLOOR, so every number this produces is a slight + * under-estimate. That is the safe direction for a latency claim: it cannot manufacture + * an improvement that is not there. + */ + class Histogram { + private val counts = AtomicLongArray(BUCKETS) + private val total = AtomicLong(0) + private val sum = AtomicLong(0) + private val max = AtomicLong(0) + + fun recordNanos(nanos: Long) = record(nanos / 1_000) + + fun record(value: Long) { + val v = if (value < 0) 0 else value + counts.incrementAndGet(indexOf(v)) + total.incrementAndGet() + sum.addAndGet(v) + max.accumulateAndGet(v) { a, b -> if (a >= b) a else b } + } + + fun reset() { + for (i in 0 until BUCKETS) counts.set(i, 0) + total.set(0) + sum.set(0) + max.set(0) + } + + fun count(): Long = total.get() + + /** Lower bound of the bucket holding the [q]th quantile, in the recorded unit. */ + fun quantile(q: Double): Long { + val n = total.get() + if (n == 0L) return 0 + val target = Math.ceil(q * n).toLong().coerceIn(1, n) + var seen = 0L + for (i in 0 until BUCKETS) { + seen += counts.get(i) + if (seen >= target) return valueOf(i) + } + return max.get() + } + + fun summaryMillis(): String { + val n = count() + if (n == 0L) return "no samples" + fun ms(us: Long) = String.format(java.util.Locale.ROOT, "%.2f", us / 1000.0) + return "n=$n p50=${ms(quantile(0.50))} p95=${ms(quantile(0.95))} " + + "p99=${ms(quantile(0.99))} max=${ms(max.get())} mean=${ms(sum.get() / n)} (ms)" + } + + /** `{"n":..,"p50":..,...}` with microsecond samples rendered as milliseconds. */ + fun jsonMillis(): String = json { us -> String.format(java.util.Locale.ROOT, "%.3f", us / 1000.0) } + + /** Same shape, but the samples are plain counts rather than durations. */ + fun jsonRaw(): String = json { it.toString() } + + private fun json(fmt: (Long) -> String): String { + val n = count() + if (n == 0L) return "{\"n\": 0}" + return "{\"n\": $n, \"p50\": ${fmt(quantile(0.50))}, \"p95\": ${fmt(quantile(0.95))}, " + + "\"p99\": ${fmt(quantile(0.99))}, \"max\": ${fmt(max.get())}, \"mean\": ${fmt(sum.get() / n)}}" + } + + fun summaryRaw(): String { + val n = count() + if (n == 0L) return "no samples" + return "n=$n p50=${quantile(0.50)} p95=${quantile(0.95)} " + + "p99=${quantile(0.99)} max=${max.get()} mean=${sum.get() / n}" + } + + private companion object { + /** 8 sub-buckets per octave; see the class doc for the resulting bound. */ + const val SUB_BITS = 3 + const val SUB_COUNT = 1 shl SUB_BITS + const val SUB_MASK = (SUB_COUNT - 1).toLong() + const val BUCKETS = 256 + + fun indexOf(v: Long): Int { + if (v < SUB_COUNT) return v.toInt() + val octave = 63 - java.lang.Long.numberOfLeadingZeros(v) + val sub = (v ushr (octave - SUB_BITS)) and SUB_MASK + val index = ((octave - SUB_BITS + 1) shl SUB_BITS) + sub.toInt() + return if (index >= BUCKETS) BUCKETS - 1 else index + } + + fun valueOf(index: Int): Long { + if (index < SUB_COUNT) return index.toLong() + val octave = (index ushr SUB_BITS) - 1 + SUB_BITS + val sub = (index and (SUB_COUNT - 1)).toLong() + return (SUB_COUNT.toLong() or sub) shl (octave - SUB_BITS) + } + } + } +} diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/TerminalCanvasRenderer.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/TerminalCanvasRenderer.kt index a9db675dd..29f22c0d2 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/TerminalCanvasRenderer.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/rendering/TerminalCanvasRenderer.kt @@ -438,6 +438,40 @@ internal fun imageCellSlice( ) } +/** + * How much of a batched run actually needs shaping. + * + * A blank draws no glyph, so trailing blanks are invisible and laying them out is pure + * cost - and a run that is nothing but blanks need not be drawn at all. An underlined run + * is the exception: there the blanks carry the rule, so the full length stands. + * + * Separated out because this is the one place the blank-batching change could drop a + * character that should have been drawn. + */ +internal fun visibleRunLength(text: CharSequence, underlined: Boolean): Int { + if (underlined) return text.length + var length = text.length + while (length > 0 && text[length - 1] == ' ') length-- + return length +} + +/** + * True when no multi-cell grapheme cluster can begin at, or reach into, [col]. + * + * ZWJ (U+200D), the skin-tone modifiers (U+1F3FB..U+1F3FF) and the regional indicators + * (U+1F1E6..U+1F1FF) are all non-ASCII, and all three can only reach this cell from + * `col..col + 2`: `checkFollowingSkinTone` looks one ahead and steps over a DWC marker, and + * `checkRegionalIndicatorSequence` requires the indicator to sit at `col` itself. Past the + * end of the line there is no character, so nothing can attach there either. + */ +internal fun isPlainAsciiRun(line: TerminalLine, col: Int, bufferLimit: Int): Boolean { + for (i in col..col + 2) { + if (i >= bufferLimit) return true + if (line.charAt(i).code >= 0x80) return false + } + return true +} + /** * Terminal canvas renderer that handles all drawing operations. * Separates rendering logic from the composable for better maintainability. @@ -549,6 +583,7 @@ object TerminalCanvasRenderer { style: TextStyle ) { if (topLeft.x >= size.width || topLeft.y >= size.height) return + FrameLatencyProbe.countDrawCall() drawText( textMeasurer = textMeasurer, text = text, @@ -566,6 +601,15 @@ object TerminalCanvasRenderer { * */ fun DrawScope.renderTerminal(ctx: RenderingContext) { + val probeStart = FrameLatencyProbe.beginFrame() + try { + renderTerminalPasses(ctx) + } finally { + FrameLatencyProbe.endFrame(probeStart) + } + } + + private fun DrawScope.renderTerminalPasses(ctx: RenderingContext) { // Cache character analysis to avoid redundant computation between passes val analysisCache = AnalysisCache(ctx.visibleRows, ctx.visibleCols) @@ -835,12 +879,19 @@ object TerminalCanvasRenderer { else androidx.compose.ui.text.font.FontStyle.Normal ).also { variants[variantIndex] = it } - drawTextClipped( - textMeasurer = ctx.textMeasurer, - text = batchText.toString(), - topLeft = Offset(x, y), - style = textStyle - ) + // A blank paints nothing unless the run is underlined, so a run that is + // only blanks, or that trails off into them, is asking the shaper to lay + // out invisible cells. Trim before layout; the underline below deliberately + // keeps the full width so an underlined gap still gets its rule. + val drawLength = visibleRunLength(batchText, batchIsUnderline) + if (drawLength > 0) { + drawTextClipped( + textMeasurer = ctx.textMeasurer, + text = batchText.substring(0, drawLength), + topLeft = Offset(x, y), + style = textStyle + ) + } // Draw underline for entire batch if needed if (batchIsUnderline) { @@ -914,13 +965,19 @@ object TerminalCanvasRenderer { continue } + // In a plain ASCII neighbourhood none of the three sequence probes below can + // fire, so the 20-char lookahead, the String it builds and the three scans are + // dead work - per cell, per frame, on every line of a log, a diff or source + // code. Anything non-ASCII nearby takes the original path unchanged. + val plainAscii = isPlainAsciiRun(line, col, bufferLimit) + // Check for ZWJ sequences using ThreadLocal builder (issue #143 optimization) val builder = zwjCheckBuilder.get() builder.setLength(0) run { var i = col var count = 0 - while (i < bufferLimit && count < 20) { + while (!plainAscii && i < bufferLimit && count < 20) { val c = line.charAt(i) if (c != CharUtils.DWC) { builder.append(c) @@ -932,9 +989,9 @@ object TerminalCanvasRenderer { val cleanText = builder.toString() // Use fast-path detection functions (issue #143 optimization) - val hasZWJ = GraphemeUtils.containsZWJ(cleanText) - val hasSkinTone = checkFollowingSkinTone(line, col, bufferLimit) - val hasRegionalIndicator = checkRegionalIndicatorSequence(line, col, bufferLimit) > 0 + val hasZWJ = !plainAscii && GraphemeUtils.containsZWJ(cleanText) + val hasSkinTone = !plainAscii && checkFollowingSkinTone(line, col, bufferLimit) + val hasRegionalIndicator = !plainAscii && checkRegionalIndicatorSequence(line, col, bufferLimit) > 0 if (hasZWJ || hasSkinTone || hasRegionalIndicator) { val graphemes = GraphemeUtils.segmentIntoGraphemes(cleanText) @@ -1020,17 +1077,27 @@ object TerminalCanvasRenderer { else -> true } + val isBlankCell = char == ' ' || char == '\u0000' + // The batching path appends one Char at a time. Keep surrogate // pairs on the per-character path so their low surrogate is not // dropped and rendered as U+FFFD by the text shaper. + // + // A blank draws no glyph, so only an underline makes it visible: it can extend + // a run whose underline state matches, whatever colour or weight it nominally + // carries. Letting it do so is what turns one drawText per WORD into one per + // line - aligned tables, indented source and powerline prompts are mostly + // blanks. It may not START a run, since leading blanks would shift the origin + // and shape nothing. val canBatch = analysis.lowSurrogate == null && !analysis.isDoubleWidth && !analysis.isEmojiOrWideSymbol && !analysis.isCursiveOrMath && !analysis.isTechnicalSymbol && - !isHidden && isBlinkVisible && char != ' ' && char != '\u0000' + !isHidden && isBlinkVisible && + (!isBlankCell || batchText.isNotEmpty()) val styleMatches = batchText.isNotEmpty() && - batchFgColor == fgColor && - batchIsBold == isBold && - batchIsItalic == isItalic && + (isBlankCell || batchFgColor == fgColor) && + (isBlankCell || batchIsBold == isBold) && + (isBlankCell || batchIsItalic == isItalic) && batchIsUnderline == isUnderline if (canBatch && (batchText.isEmpty() || styleMatches)) { @@ -1041,7 +1108,9 @@ object TerminalCanvasRenderer { batchIsItalic = isItalic batchIsUnderline = isUnderline } - batchText.append(char) + // NUL is a blank cell, not a glyph: appending it verbatim would hand the + // shaper a control character to draw. + batchText.append(if (isBlankCell) ' ' else char) } else { flushBatch() @@ -1599,7 +1668,7 @@ object TerminalCanvasRenderer { /** * Check if current character is followed by skin tone modifier. */ - private fun checkFollowingSkinTone(line: TerminalLine, col: Int, width: Int): Boolean { + internal fun checkFollowingSkinTone(line: TerminalLine, col: Int, width: Int): Boolean { var checkCol = col val currentChar = line.charAt(checkCol) @@ -1638,7 +1707,7 @@ object TerminalCanvasRenderer { * - [High1][Low1][DWC][High2][Low2] = 5 chars (DWC after first indicator) * - [High1][Low1][DWC][High2][Low2][DWC] = 6 chars (DWC after both) */ - private fun checkRegionalIndicatorSequence(line: TerminalLine, col: Int, width: Int): Int { + internal fun checkRegionalIndicatorSequence(line: TerminalLine, col: Int, width: Int): Int { if (col + 3 >= width) return 0 // Need at least 4 chars for 2 surrogate pairs val c1 = line.charAt(col) diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/settings/TerminalSettings.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/settings/TerminalSettings.kt index 26d50b3cf..645d4f7fd 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/settings/TerminalSettings.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/settings/TerminalSettings.kt @@ -620,14 +620,20 @@ data class TerminalSettings( /** * Performance optimization mode. - * - "latency": Optimized for interactive responsiveness (faster command response, lower throughput) - * - "throughput": Optimized for bulk output (higher throughput, slightly higher latency) - * - "balanced": Balance between latency and throughput (default) + * - "latency" (default): the data stream never waits for more bytes than it already has + * - "throughput": waits up to 10 ms on buffer exhaustion to batch more aggressively + * - "balanced": waits up to 5 ms * - * Use "latency" for: SSH sessions, interactive commands, shell usage - * Use "throughput" for: Large file operations, build logs, data processing + * The wait happens in `readNonControlCharacters` with the printable characters already + * in hand, so on an interactive echo it is pure added latency. Measured: switching the + * default from "balanced" to "latency" took byte-to-pixel p50 from 16.4 ms to 12.3 ms + * with nothing else changed (`benchmark_results/LATENCY_BASELINE_2026-08-27.md`). The + * throughput this was trading for is not visible at 8 KB chunk sizes. + * + * Use "throughput" only for a session that is genuinely bulk-output bound and whose + * latency nobody is watching. */ - val performanceMode: String = "balanced", + val performanceMode: String = "latency", /** * Maximum refresh rate in FPS (0 = unlimited) diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/terminal/BlockingTerminalDataStream.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/terminal/BlockingTerminalDataStream.kt index 91e38adda..0af392f49 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/terminal/BlockingTerminalDataStream.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/terminal/BlockingTerminalDataStream.kt @@ -1,10 +1,12 @@ package ai.rever.bossterm.compose.terminal +import ai.rever.bossterm.compose.rendering.FrameLatencyProbe import ai.rever.bossterm.terminal.TerminalDataStream import ai.rever.bossterm.terminal.util.GraphemeUtils import ai.rever.bossterm.terminal.util.GraphemeBoundaryUtils import java.io.IOException import java.util.concurrent.BlockingQueue +import java.util.concurrent.ConcurrentLinkedQueue import java.util.concurrent.LinkedBlockingQueue import java.util.concurrent.TimeUnit @@ -59,6 +61,34 @@ class BlockingTerminalDataStream( private val buffer = StringBuilder() private var position = 0 private val dataQueue: BlockingQueue = LinkedBlockingQueue() + + /** + * Arrival timestamps for the chunks in [dataQueue], one per entry, in the same order. + * + * Kept alongside rather than inside the queue so the shipped type stays `String` and + * nothing on the hot path changes when [FrameLatencyProbe] is off - the queue is only + * ever written under `FrameLatencyProbe.enabled`. Stamped here, before the poll wait + * below, so that whatever the performance mode spends waiting lands inside the + * measurement instead of ahead of it. + */ + private val arrivalNanos = ConcurrentLinkedQueue() + + /** Offer a chunk plus, when probing, its arrival time. Keeps the two queues aligned. */ + private fun enqueue(chunk: String) { + if (FrameLatencyProbe.enabled) arrivalNanos.offer(System.nanoTime()) + dataQueue.offer(chunk) + } + + /** Pair every successful take from [dataQueue] with its arrival stamp. */ + private fun took(chunk: String?): String? { + if (FrameLatencyProbe.enabled && chunk != null && chunk != CLOSE_SENTINEL) { + arrivalNanos.poll()?.let { stamped -> + FrameLatencyProbe.markArrival(stamped) + FrameLatencyProbe.markDequeued(stamped, chunk.length) + } + } + return chunk + } @Volatile private var closed = false private val pushBackStack = mutableListOf() @@ -174,14 +204,14 @@ class BlockingTerminalDataStream( val completeData = fullData.substring(0, lastCompleteIndex) if (completeData.isNotEmpty()) { - dataQueue.offer(completeData) + enqueue(completeData) // Invoke debug callback only for complete data debugCallback?.invoke(completeData) notifyRawOutput(completeData) } } else { // All graphemes are complete - dataQueue.offer(fullData) + enqueue(fullData) debugCallback?.invoke(fullData) notifyRawOutput(fullData) } @@ -223,7 +253,7 @@ class BlockingTerminalDataStream( onTerminalStateChanged?.invoke() // Need more data - behavior depends on performance mode (issue #146) - val chunk = if (closed) { + val chunk = took(if (closed) { dataQueue.poll() // Non-blocking if closed } else { when (performanceMode) { @@ -236,7 +266,7 @@ class BlockingTerminalDataStream( // BALANCED: Poll with 10ms timeout as middle ground PerformanceMode.BALANCED -> dataQueue.poll(10, TimeUnit.MILLISECONDS) } - } + }) // Check for close sentinel if (chunk == CLOSE_SENTINEL) { @@ -286,14 +316,14 @@ class BlockingTerminalDataStream( // Compact buffer to prevent memory leak (issue #179) compactBuffer() - val chunk = when (performanceMode) { + val chunk = took(when (performanceMode) { // LATENCY: Non-blocking - return immediately with what we have PerformanceMode.LATENCY -> dataQueue.poll() // THROUGHPUT: Wait longer for better batching PerformanceMode.THROUGHPUT -> dataQueue.poll(10, TimeUnit.MILLISECONDS) // BALANCED: Short wait for moderate batching PerformanceMode.BALANCED -> dataQueue.poll(5, TimeUnit.MILLISECONDS) - } + }) if (chunk != null && chunk != CLOSE_SENTINEL) { buffer.append(chunk) } else { diff --git a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ui/ProperTerminal.kt b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ui/ProperTerminal.kt index 6f6453df3..43f4b412f 100644 --- a/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ui/ProperTerminal.kt +++ b/compose-ui/src/desktopMain/kotlin/ai/rever/bossterm/compose/ui/ProperTerminal.kt @@ -91,6 +91,7 @@ import ai.rever.bossterm.compose.search.SearchBar import ai.rever.bossterm.compose.rendering.RenderingContext import ai.rever.bossterm.compose.rendering.RenderableBlock import ai.rever.bossterm.compose.rendering.ImageRenderer +import ai.rever.bossterm.compose.rendering.FrameLatencyProbe import ai.rever.bossterm.compose.rendering.TerminalCanvasRenderer import ai.rever.bossterm.terminal.model.TerminalLine import kotlin.math.abs @@ -2054,6 +2055,7 @@ fun ProperTerminal( // after it returns, never during. myLock is reentrant, so the nested acquisitions // below are free, and this replaces TWO acquisitions per composition with one: the // type-ahead column used to take it again, live, outside the capture entirely. + val probeCaptureStart = FrameLatencyProbe.startTiming() textBuffer.lock() try { // Type-ahead FIRST: its reset path clears predictions off the lines, and doing @@ -2068,6 +2070,7 @@ fun ProperTerminal( ) } finally { textBuffer.unlock() + FrameLatencyProbe.recordSnapshot(probeCaptureStart) } } } diff --git a/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollectorTrimTest.kt b/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollectorTrimTest.kt new file mode 100644 index 000000000..19d65b216 --- /dev/null +++ b/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/debug/DebugDataCollectorTrimTest.kt @@ -0,0 +1,86 @@ +package ai.rever.bossterm.compose.debug + +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertFalse +import kotlin.test.assertTrue + +/** + * The chunk ring is trimmed against a tracked counter rather than `ConcurrentLinkedQueue.size()`, + * which is O(n) and was being called once per chunk that crossed the tty. + * + * A tracked counter can drift from the queue it shadows, and drift is silent and directional: + * too high and the ring evicts live entries forever, too low and it grows without bound. Neither + * shows up as an exception, and `read_debug_console` would just quietly return the wrong window + * of history. So the invariant is pinned here rather than assumed. + */ +class DebugDataCollectorTrimTest { + + @Test + fun ringStaysAtItsBoundUnderSustainedRecording() { + val max = 16 + val collector = DebugDataCollector(tab = null, maxChunks = max, maxSnapshots = 4) + + repeat(max * 20) { collector.recordChunk("chunk-$it", ChunkSource.PTY_OUTPUT) } + + assertEquals(max, collector.getChunkCount(), "ring should sit exactly at its bound") + assertEquals(max, collector.getDebugChunks().size, "counter and queue must agree") + } + + @Test + fun theRetainedWindowIsTheMostRecent() { + // Evicting from the wrong end would keep the oldest history and silently drop + // everything a caller actually wants. + val max = 8 + val collector = DebugDataCollector(tab = null, maxChunks = max, maxSnapshots = 4) + repeat(50) { collector.recordChunk("chunk-$it", ChunkSource.PTY_OUTPUT) } + + val kept = collector.getDebugChunks().map { String(it.data) } + assertEquals((42..49).map { "chunk-$it" }, kept) + } + + @Test + fun clearResetsTheCounterAlongsideTheQueue() { + // The failure this guards is nasty: a counter left high after a clear makes every + // later record evict a live entry, so the ring never refills. + val max = 8 + val collector = DebugDataCollector(tab = null, maxChunks = max, maxSnapshots = 4) + repeat(40) { collector.recordChunk("before-$it", ChunkSource.PTY_OUTPUT) } + collector.clear() + assertEquals(0, collector.getChunkCount()) + + repeat(5) { collector.recordChunk("after-$it", ChunkSource.PTY_OUTPUT) } + assertEquals(5, collector.getChunkCount(), "ring must refill after a clear") + assertEquals(5, collector.getDebugChunks().size) + } + + @Test + fun growingBelowTheBoundDoesNotEvict() { + val collector = DebugDataCollector(tab = null, maxChunks = 100, maxSnapshots = 4) + repeat(30) { collector.recordChunk("c-$it", ChunkSource.PTY_OUTPUT) } + assertEquals(30, collector.getChunkCount()) + assertTrue(collector.getDebugChunks().first().data.concatToString() == "c-0") + } + + @Test + fun snapshotsAreCapturedWheneverEitherDebugFlagIsSet() { + // This is a REGRESSION TEST for a bug that shipped. TerminalTab has two debug + // flags: `debugEnabled` (background collection, from settings) and + // `debugPanelVisible` (the UI, toggled with Cmd/Ctrl+Shift+D). The gate originally + // read only the first, so pressing Cmd+Shift+D opened a permanently empty panel - + // opening the panel does not set the collection flag. + val collector = DebugDataCollector(tab = null, maxChunks = 8, maxSnapshots = 4) + + // The case that was broken: panel open, collection flag untouched. + assertTrue( + collector.shouldCaptureState(collectionEnabled = false, panelVisible = true), + "opening the debug panel must start capturing, or the panel renders empty" + ) + // Background collection with the panel closed is the other real configuration. + assertTrue(collector.shouldCaptureState(collectionEnabled = true, panelVisible = false)) + assertTrue(collector.shouldCaptureState(collectionEnabled = true, panelVisible = true)) + + // And the default, which is the whole point of the gate: no deep copy per tick. + assertFalse(collector.shouldCaptureState(collectionEnabled = false, panelVisible = false)) + } +} diff --git a/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/rendering/FrameLatencyProbeTest.kt b/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/rendering/FrameLatencyProbeTest.kt new file mode 100644 index 000000000..9e78aca38 --- /dev/null +++ b/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/rendering/FrameLatencyProbeTest.kt @@ -0,0 +1,135 @@ +package ai.rever.bossterm.compose.rendering + +import kotlin.test.AfterTest +import kotlin.test.BeforeTest +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertTrue + +/** + * The probe exists to decide whether a latency change helped. A histogram that reports + * plausible-but-wrong percentiles would make every later measurement worthless while + * looking fine, so the bucketing is pinned here rather than trusted. + */ +class FrameLatencyProbeTest { + + private var wasEnabled = false + + @BeforeTest + fun setUp() { + wasEnabled = FrameLatencyProbe.enabled + FrameLatencyProbe.enabled = true + FrameLatencyProbe.reset() + } + + @AfterTest + fun tearDown() { + FrameLatencyProbe.reset() + FrameLatencyProbe.enabled = wasEnabled + } + + @Test + fun bucketsRoundTripWithinStatedError() { + // Four sub-buckets per octave puts the worst case at 1/8 of the value. A bucket + // that silently widened would show up as an under-reported p99, which is exactly + // the number a latency claim rests on. + val h = FrameLatencyProbe.Histogram() + var v = 1L + while (v < 4_000_000L) { + h.reset() + h.record(v) + val reported = h.quantile(0.5) + assertTrue( + reported <= v && v - reported <= v / 8 + 1, + "value $v reported as $reported, outside the 12.5% bucket bound" + ) + v = v * 3 / 2 + 1 + } + } + + @Test + fun quantilesTrackAKnownDistribution() { + val h = FrameLatencyProbe.Histogram() + // 990 samples at 1000, 10 at 100000. p50 and p95 must land on the body, p99 on it + // too (the 10 outliers are the top 1%, so p99 is the last body sample), and only + // max should see the tail. Getting this backwards is the classic percentile bug. + repeat(990) { h.record(1_000) } + repeat(10) { h.record(100_000) } + + assertEquals(1000L, h.count()) + assertWithinBucket(1_000, h.quantile(0.50)) + assertWithinBucket(1_000, h.quantile(0.95)) + assertWithinBucket(1_000, h.quantile(0.99)) + assertWithinBucket(100_000, h.quantile(1.0)) + } + + @Test + fun emptyHistogramReportsNothingRatherThanZeroLatency() { + val h = FrameLatencyProbe.Histogram() + assertEquals(0L, h.count()) + assertEquals(0L, h.quantile(0.5)) + assertTrue(h.jsonMillis().contains("\"n\": 0"), h.jsonMillis()) + // A reader must be able to tell "no samples" from "instant", or an unexercised + // build reads as a win. + assertTrue(!h.jsonMillis().contains("p50"), h.jsonMillis()) + } + + @Test + fun frameKeepsTheEarliestPendingArrival() { + // A paint draws the whole buffer, so it renders every chunk that arrived before it. + // The latency that matters is the one the OLDEST un-drawn chunk experienced; a + // later arrival overwriting it would under-report exactly when output is bursty. + val now = System.nanoTime() + FrameLatencyProbe.markArrival(now - 50_000_000L) // 50 ms ago + FrameLatencyProbe.markArrival(now - 1_000_000L) // 1 ms ago, must not win + + val start = FrameLatencyProbe.beginFrame() + FrameLatencyProbe.endFrame(start) + + assertEquals(1L, FrameLatencyProbe.byteToPaint.count()) + val p50 = FrameLatencyProbe.byteToPaint.quantile(0.5) + assertTrue(p50 >= 40_000, "expected roughly 50ms in microseconds, got $p50") + } + + @Test + fun aFrameWithNoNewDataIsNotCountedAsLatency() { + // Blink, resize and scroll all repaint without any byte having arrived. Recording + // those would flood the histogram with fabricated near-zero samples and drag every + // percentile down. + val start = FrameLatencyProbe.beginFrame() + FrameLatencyProbe.endFrame(start) + + assertEquals(0L, FrameLatencyProbe.byteToPaint.count()) + assertEquals(1L, FrameLatencyProbe.paintCost.count()) + } + + @Test + fun drawCallsAreCountedPerFrameNotCumulatively() { + repeat(3) { + val start = FrameLatencyProbe.beginFrame() + repeat(7) { FrameLatencyProbe.countDrawCall() } + FrameLatencyProbe.endFrame(start) + } + assertEquals(3L, FrameLatencyProbe.drawCallsPerFrame.count()) + assertEquals(7L, FrameLatencyProbe.drawCallsPerFrame.quantile(0.5)) + } + + @Test + fun disabledProbeRecordsNothing() { + FrameLatencyProbe.enabled = false + FrameLatencyProbe.markArrival(System.nanoTime() - 10_000_000L) + val start = FrameLatencyProbe.beginFrame() + FrameLatencyProbe.countDrawCall() + FrameLatencyProbe.endFrame(start) + + assertEquals(0L, FrameLatencyProbe.byteToPaint.count()) + assertEquals(0L, FrameLatencyProbe.paintCost.count()) + } + + private fun assertWithinBucket(expected: Long, actual: Long) { + assertTrue( + actual <= expected && expected - actual <= expected / 8 + 1, + "expected ~$expected, got $actual" + ) + } +} diff --git a/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/rendering/PlainAsciiFastPathTest.kt b/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/rendering/PlainAsciiFastPathTest.kt new file mode 100644 index 000000000..877542476 --- /dev/null +++ b/compose-ui/src/desktopTest/kotlin/ai/rever/bossterm/compose/rendering/PlainAsciiFastPathTest.kt @@ -0,0 +1,138 @@ +package ai.rever.bossterm.compose.rendering + +import ai.rever.bossterm.terminal.TextStyle +import ai.rever.bossterm.terminal.model.CharBuffer +import ai.rever.bossterm.terminal.model.TerminalLine +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertFalse +import kotlin.test.assertTrue + +/** + * The ASCII fast path skips a 20-char lookahead and three sequence probes. It is only + * sound if it never skips a probe that would have fired: one false positive turns a flag, + * a family emoji or a skin-toned hand into mojibake, and none of the existing tests would + * notice because they never render. + * + * So rather than trusting the reasoning, this compares the fast path against the very + * probes it elides, over a corpus that includes every sequence kind the renderer special + * cases, at every column. + */ +class PlainAsciiFastPathTest { + + private val corpus = listOf( + "plain ascii text 0123456789 !@#\$%^&*()", + "ls -la drwxr-xr-x 12 user staff 384 Aug 26 10:11 src", + "👨‍💻 developer", // ZWJ: man technologist + "👩‍👩‍👧 fam", // ZWJ family + "flag 🇺🇸 usa", // regional indicators + "wave 👋🏽 done", // skin tone modifier + "check ✔️ mark", // variation selector + "cjk 你好 world", // wide chars + "powerline  prompt", + "a‍b", // ZWJ between ASCII + "x🏽y", // skin tone right after ASCII + ) + + @Test + fun fastPathNeverSkipsAProbeThatWouldHaveFired() { + for (text in corpus) { + val line = terminalLine(text) + val limit = line.length() + for (col in 0 until limit) { + if (!TerminalCanvasRendererTestAccess.isPlainAsciiRun(line, col, limit)) continue + + assertFalse( + TerminalCanvasRenderer.checkFollowingSkinTone(line, col, limit), + "skin tone at col $col of ${text.escaped()} would have been skipped" + ) + assertTrue( + TerminalCanvasRenderer.checkRegionalIndicatorSequence(line, col, limit) == 0, + "regional indicator at col $col of ${text.escaped()} would have been skipped" + ) + // A grapheme cluster can only pull a ZWJ into THIS cell from the very next + // one, so ASCII at col and col+1 is what rules the ZWJ branch out. + assertTrue(line.charAt(col).code < 0x80, "col $col of ${text.escaped()} is not ASCII") + if (col + 1 < limit) { + assertTrue( + line.charAt(col + 1).code < 0x80, + "col ${col + 1} of ${text.escaped()} is not ASCII" + ) + } + } + } + } + + @Test + fun fastPathStillFiresOnOrdinaryText() { + // The guard must not be so conservative that it never engages - a fast path that + // is always off would pass the test above trivially while changing nothing. + val line = terminalLine("the quick brown fox jumps over the lazy dog") + val limit = line.length() + val engaged = (0 until limit).count { + TerminalCanvasRendererTestAccess.isPlainAsciiRun(line, col = it, bufferLimit = limit) + } + assertTrue(engaged == limit, "expected the fast path at all $limit columns, got $engaged") + } + + @Test + fun fastPathDisengagesAroundNonAscii() { + val line = terminalLine("ab你cd") + val limit = line.length() + // The wide char sits at index 2, and the guard looks at col..col+2, so columns 0, + // 1 and 2 must all decline. + assertFalse(TerminalCanvasRendererTestAccess.isPlainAsciiRun(line, 0, limit)) + assertFalse(TerminalCanvasRendererTestAccess.isPlainAsciiRun(line, 1, limit)) + assertFalse(TerminalCanvasRendererTestAccess.isPlainAsciiRun(line, 2, limit)) + assertTrue(TerminalCanvasRendererTestAccess.isPlainAsciiRun(line, 3, limit)) + } + + private fun String.escaped(): String = replace(Regex("[^\\x20-\\x7E]")) { m -> + "\\u%04X".format(m.value.first().code) + } + + private fun terminalLine(text: String): TerminalLine = TerminalLine( + TerminalLine.TextEntry(TextStyle.EMPTY, CharBuffer(text)) + ) +} + +/** File-private top-level functions are not reachable from a test; this is. */ +internal object TerminalCanvasRendererTestAccess { + fun isPlainAsciiRun(line: TerminalLine, col: Int, bufferLimit: Int): Boolean = + ai.rever.bossterm.compose.rendering.isPlainAsciiRun(line, col, bufferLimit) +} + +/** + * Blanks now extend a batched run instead of breaking it, which is what collapses one + * drawText per word into one per line. The risk that buys is dropping a character that + * should have been drawn, so the trim is pinned here. + */ +class VisibleRunLengthTest { + + @Test + fun trailingBlanksAreNotShaped() { + assertEquals(3, visibleRunLength("abc ", underlined = false)) + assertEquals(0, visibleRunLength(" ", underlined = false)) + assertEquals(0, visibleRunLength("", underlined = false)) + } + + @Test + fun interiorBlanksAreKept() { + // The whole point: "a b" must stay one run of five cells, not be cut to "a". + assertEquals(5, visibleRunLength("a b", underlined = false)) + assertEquals(8, visibleRunLength("a b c", underlined = false)) + } + + @Test + fun underlinedRunsKeepTheirTrailingBlanks() { + // The blanks carry the rule, so trimming them would shorten a visible underline. + assertEquals(6, visibleRunLength("abc ", underlined = true)) + assertEquals(4, visibleRunLength(" ", underlined = true)) + } + + @Test + fun nonBlankRunsAreUntouched() { + assertEquals(3, visibleRunLength("abc", underlined = false)) + assertEquals(3, visibleRunLength("abc", underlined = true)) + } +}