Back to the blog

The benchmark said 27x faster. It felt worse.

Resizing a pane in TUIOS lagged behind the mouse. Go's profiling tools found the cause, killed two theories I was sure about, and then spent three rounds accurately measuring the wrong thing.

Gaurav Gosain

Dragging a pane divider in TUIOS trailed the mouse. Worse the longer you dragged.

That last detail is the whole diagnosis, though I nearly skipped past it. A uniformly slow frame feels the same at the start of a gesture as at the end. Something that degrades as you go is a queue you are not draining fast enough.

Backlog, not slow frame

Every mouse motion event composed a full frame. A frame during a tiling resize costs 3.3 to 6.7 ms, which caps the drain rate somewhere around 150 to 300 events per second. A drag emits roughly one event per cell crossed, and moving a mouse across a terminal briskly beats that comfortably.

So the queue grows for the duration of the drag, and what you see is wherever the pointer was some number of events ago. Stop moving and it catches up. That is why it read as lag rather than as slowness.

The fix bounds redraws to one per frame interval. Every event's geometry is still applied before the draw decision, so no input is dropped and the layout still settles exactly where you released the button. Only the redundant intermediate frames go.

Per motion event, measured through the real Update and View rather than around them. Drain rate goes from a few hundred events per second to tens of thousands, which puts a backlog out of reach of any pointer.
windowsbefore (us)after (us)
24,07024
45,31642
96,663115
Per motion event, measured through the real Update and View rather than around them. Drain rate goes from a few hundred events per second to tens of thousands, which puts a backlog out of reach of any pointer.

The difference is easier to feel than to read:

queue 0 · lag 0px
Drag the divider. With coalescing off, one motion event composes one frame, so the queue drains at one event per frame cost while the drag emits one event per cell crossed. Keep moving and the gap grows; stop and it catches up. That growth is what separates a backlog from a slow frame. Turn coalescing on and the same drag pins to the pointer. Either way the divider lands exactly where you released, because every event still updates the geometry and only the redundant frames are dropped. The slider spans the measured range for a real resize frame.

The tooling, and the flags that mattered

Go's benchmark support did most of the work, and the useful flags are not the obvious ones.

go test -run XXX -bench BenchmarkResizeMotion -benchmem -count=5 ./internal/input/

-run XXX matches no test, so nothing but the benchmark runs. -benchmem gives allocations per operation, which mattered more than nanoseconds in two places below. -count=5 runs the whole thing five times, and the spread across those runs is the only thing that tells you whether a 15% improvement is real. Absolute timings on this machine drift with thermal state, so anything I compared had to be interleaved rather than measured an hour apart.

TUIOS wires up net/http/pprof behind a flag:

if pprofAddr != "" {
    runtime.SetBlockProfileRate(1)
    runtime.SetMutexProfileFraction(1)
    go func() { _ = http.ListenAndServe(pprofAddr, nil) }()
}

Block and mutex profiling are off by default in Go and cost real overhead when on, which is why they sit behind the same flag rather than being always enabled. For a program that spends its life waiting on PTY reads and holding locks, those are the two profiles that explain anything.

Four hypotheses. Two wrong.

I wrote them down before measuring, mostly so that being wrong would stay visible afterwards instead of quietly evaporating.

One: the whole-tree ratio sync is expensive. It recomputes every split ratio in the BSP tree on every motion event, which sounds bad. Measured at 6 to 86 us against a multi-millisecond frame. Roughly 1%. I would have spent a day there.

Two: damage tracking is doing nothing. Mine, and wrong in a way that still stings. I read a benchmark where the one-dirty case measured slightly slower than all-dirty and concluded the tracking was dead weight. At one window, one-dirty and all-dirty are the same case. Identical timings prove nothing. At four and nine windows it does substantial work: 929 against 1343 us, and 737 against 1221 us. I had compared a thing to itself, written it down as settled, and built the next hour of work on top of it.

Three: the tick throttle is not helping. True. SlowTickCmd governed the periodic tick during a drag while motion events drove their own renders anyway, so it lowered the ceiling without touching the flood. Removed.

Four: PTY resizes are firing per event. Not happening, and worth having checked, because a TIOCSWINSZ per motion event would produce exactly these symptoms. Confirming it was already deferred to drag completion cost one grep.

Two of four wrong is about my usual rate. That is the argument for writing them down.

Fixing the top cost promotes the next one

With renders coalesced, the handler ran on every event while renders did not, so the handler became the new floor. A gap appeared that had been sitting invisible underneath the old cost.

The non-shared path is nearly flat from 4 to 9 windows. The shared path more than doubles. The shape gave it away before the gap did, because flat against scaling tells you which code is doing per-window work it should not be.
windowsshared borders off (ns)shared borders on (ns)
47,84812,324
98,21528,650
The non-shared path is nearly flat from 4 to 9 windows. The shared path more than doubles. The shape gave it away before the gap did, because flat against scaling tells you which code is doing per-window work it should not be.

Allocations said it more bluntly: 10,665 B in 8 allocations against 57,238 B in 34, per event, at nine windows.

The culprit was SyncBSPTreeFromGeometry running on every motion event, rebuilding a geometry map over every window and re-deriving every ratio in the tree. Same medicine as the renders: defer the sync to the frame that actually draws. The drag-completion sync stays unconditional, because a stale tree means the next retile silently discards the user's resize. After the change, 7,215 and 7,278 ns at four and nine windows, flat again, back to 8 allocations.

A performance conclusion has a shelf life. Hypothesis one, correctly measured at 1% of a frame, was the bottleneck an hour later, because I had removed everything that used to dwarf it.

The performance fix caused a rendering bug

Deferring the ratio sync meant the separator overlay could draw from tree state that lagged the real window geometry. The overlay takes divider positions from the tree and the highlight from live geometry, so mid-drag it drew the divider where the drag had already left, in the unfocused colour, because that column was no longer on the focused pane's perimeter.

It looked like a red afterimage trailing the cyan separator.

My first fix put the flush on the paths that change geometry, which is the obvious place and the wrong one. Any frame composed for another reason bypassed it, and PTYDataMsg composes constantly during a real drag, because the terminals in the other panes are still producing output. Which is why it showed up constantly in use and needed interleaved PTY output to reproduce in a test.

The flush belongs in View, immediately before composing. Geometry can be applied whenever, but the ratios have to agree with it on any frame that reaches the screen.

Eighteen of twenty-four mid-drag frames wrong before, none after. Removing the flush with the test in place fails twenty-four of twenty-four.

Where micro-optimisation could not help

Two bugs where tuning the hot path would have been wasted effort.

A quadratic behind a passing benchmark

Typing in the browser client was unusable. getLine walked the whole viewport for every row, making a frame O(rows squared times cols).

No amount of constant-factor work closes a quadratic gap. It took three changes, each of which promoted the next bottleneck:

changeChromiumFirefox
reuse one view per viewport walk6.3 to 1.3 ms11.64 to 3.32 ms
preallocated ring for getLine rows0.3 to 0.1 ms2.24 to 0.34 ms
read only the rows the VT marked dirty1.4 to 0.0 ms3.90 to 0.12 ms

Full repaint stayed at 11.5 to 11.2 ms through that last one, which is correct. That path has no dirty rows to skip. A change that improved it too would have meant I was measuring something else by accident.

An aside from the same stretch of work, because it wasted three runs before I saw it. The browser test harness reused an already-running server when outside CI, and the client assets are compiled into the Go binary. So a server left over from an earlier build kept serving the previous client, and editing the client then rerunning the tests exercised the old build, with nothing logged. Three confident results about code that was never loaded. The harness now rebuilds per run, and I trust "the test passed" a little less than I used to.

A freeze no profiler would find

The multiplexer locked up within seconds of any command producing output.

The render path took a window's I/O read lock, then called a function that took the same lock again. Go's RWMutex is not reentrant for readers. If a writer queues between the two acquisitions, the second read blocks behind the writer, the writer blocks behind the first read, and everything stops.

There is no hot path to profile here. The program is not slow, it is stopped. What finds it is SIGQUIT with GOTRACEBACK=all, reading the goroutine dump, and spotting two frames of the same stack holding and wanting the same lock. The fix was hoisting the cursor query above the lock.

There was also an optimisation I measured and threw away entirely: porting correct grapheme width tables from ghostty-vt, which changed nothing because cluster advance was never a per-codepoint question in the first place. That one got its own post.

What a benchmark cannot tell you

Later in the same work, shared-border drags still felt wrong. The benchmark disagreed, emphatically. At nine windows a frame had gone from 8,981,357 ns to 326,214 ns across this work, which is 27 times faster, and the shared-border path had improved more than the plain one.

Then I used it, and it felt worse. Not marginally. Worse than before I started.

Three reasons the measurement could not see it.

Building an animation object is cheap. The cost was that panes never arrived at the pointer, because each frame cancelled the previous animation and started a fresh 300 ms ease toward a target that had already moved. Not arriving is felt, never timed.

The daemon resize callback is nil under test. So 205 socket round trips per 30 frames cost a nil check in the benchmark and a real round trip in production.

And the benchmark drove motion into idle terminals, where coalescing made almost every frame a cache hit. The layout reapply ran once in twenty motion events under test. In use, with output flowing, it ran on every frame.

What found it was instrumenting the running program: log the pointer position, the grabbed divider, and every window whose geometry changed, then do the drag and read the log. One drag showed five windows moving where two should have, one of them reversing direction twenty-two times. The benchmarks had been accurately measuring the wrong thing for three rounds. What fell out of that log, three separate defects and one candidate that turned out to be correct behaviour, became its own post.

When the numbers and the experience disagree, the experience wins. The benchmark is not wrong. It is answering the question you encoded, precisely, and it has no opinion on whether that was the right question.