A wait that made the pane 197 times slower

tuios wait-for window-output blocks until a pane prints something that matches a pattern. Agents use it to wait for a build or a test run without a loop of capture-pane and sleep. The daemon does the watching.

The wait is supposed to be free for the pane it watches. It was not. With a waiter pending, seq 1 500000 ran more than three times slower. After I fixed that, the same test on the libghostty-vt backend said 197.6 times slower. This post is about both numbers, and why the first fix could not touch the second.

One capture per read

A wait for output has to look at the pane's text. It captures the pane, the history and the screen as plain text, and runs the pattern over it. It must hold the pane's emulator lock while it reads, so the emulator cannot change the text halfway through.

The question is when to look. The daemon raises an output event each time it reads from the pane's PTY, and the waiter looked on every event. On a pane that floods, that is thousands of looks a second, and each one read the whole history under the lock. The emulator writes under the same lock. So the waiter and the emulator took turns, and the flood waited.

The test

The budget is a test in internal/session, TestWaitForOutputDoesNotSlowFlood. It runs a real daemon with a real shell, and times the same flood with and without a waiter:

1. Fill the history with seq 1 20000. A full history is what makes one capture expensive.
2. Time seq 1 500000 twice and keep the faster run.
3. Start a waiter on its own connection, with a pattern that never matches.
4. Time the flood twice more, and compare.

Step 2 is the positive half. The run without the waiter is the control the run with it is measured against, in the same fixture, on the same machine.

The clock stops at an awkward place. The shell finishing tells you nothing about the emulator, because the daemon's read loop queues several megabytes ahead of it. The waiter slows the emulator, not the shell. So the flood ends when the shell has touched a marker file and the emulator has applied every byte the PTY gave it:

func caughtUp(p *PTY) bool {
	p.outputMu.Lock()
	read := p.outputSeq
	p.outputMu.Unlock()
	p.terminalMu.RLock()
	applied := p.vtSeq
	p.terminalMu.RUnlock()
	return applied >= read
}

The test fails if the flood with the waiter takes more than one and a half times as long, plus 100 ms of room for a shared machine.

Look less often

f7ea5e40 caps the looks. A waiter captures at most once every 50 ms. An event inside that gap does not capture. It arms one deferred check at the end of the gap, and more events in the same gap arm nothing more:

case <-sub.ch:
	if deferred != nil {
		continue
	}
	if wait := waitOutputMinGap - time.Since(lastCheck); wait > 0 {
		gapTimer.Reset(wait)
		deferred = gapTimer.C
		continue
	}
	if matches() {
		return waitMatched(/* ... */), nil
	}
case <-deferred:
	deferred = nil
	if pty.currentCaptureState() == checked {
		continue
	}
	if matches() {
		return waitMatched(/* ... */), nil
	}

The deferred check is what keeps this correct. Output that arrives in the gap, and then nothing after it, is still checked at the end of the gap. So the last output of a burst is always seen. When the deferred check fires, it first asks whether the pane changed since the last capture. If not, it skips the capture.

The gap is measured from the end of the last capture, not its start. On a pane whose capture is slow, that still leaves the lock alone between looks.

The numbers, from the commit: with a waiter, the flood was 3.27 to 3.57 times slower before, and 0.92 to 0.98 times after. The negative control cut the coalescing, so every event captures again. The test failed 3 of 3 runs, at 3.37, 3.27 and 3.57 times.

The same test on the other backend

tuios has two terminal emulators. The pure Go one is the default. The other is libghostty-vt, Ghostty's terminal core as a library, built in with -tags ghostty. A plain go test ./... compiles neither the ghostty backend nor its tests.

With -tags ghostty, TestWaitForOutputDoesNotSlowFlood said 197.6 times.

The coalescing was in. The waiter looked at most once every 50 ms. But on this backend, one look took about 200 ms for a full 10,000-line history at 80 columns, and all of it under the lock.

The pure Go emulator had stopped paying that cost in September. Its plain capture used to decode every history line into cells and walk the cells back to text. docs/perf.md records the fix: Emulator.AppendScrollbackText writes the text straight from the packed history, and one capture of a full ring at 80 columns went from 29.9 ms to 1.25 ms. The same entry ends the paragraph with: "the ghostty backend keeps the line by line loop." That loop read the history through the library one cell at a time, with one GridRef per cell.

So the 50 ms gap fixed how often the waiter looked, and on the ghostty backend each look took longer than the gap. In the words of 23936fa8: "On a flooding pane the lock was held most of the time."

Ask the library for text

libghostty-vt has a formatter that writes a selection as plain text in one call. 23936fa8 gives the ghostty backend its own AppendScrollbackText, which selects the whole history and asks for it:

sel := &gh.Selection{Start: *start, End: *end}
text, err := src.SelectionFormatString(gh.WithSelection(sel), gh.WithSelectionTrim(true), gh.WithSelectionUnwrap(false))

It would be a two-line fix if the formatter's text were the same as the old text. It is not, in two places.

Trailing spaces. The formatter trims every trailing space. The capture it replaces goes through uv.Line.String, which keeps a trailing space that has a style or a link. A red cell with a space in it is text, to a capture. So a row that may end in such a space is still read cell by cell. To find those rows, the backend asks the formatter for the same history a second time, as VT, and scans it: a row that prints a space while an SGR attribute is set, after its last other character, is marked. A row the library says holds a hyperlink is marked too. The scan is conservative. Any SGR but a plain reset counts as set.

Blank rows at the end. The formatter leaves out blank rows at the end of the history. Those are read back one by one, and each must be blank. If one is not, the formatter's lines are not the rows, and the whole history is read line by line as before.

That last rule is the general one. If the formatter's text does not line up with the rows, the code falls back to the old loop. A change in the library's output can make a capture slow again. It cannot shift a line.

The commit's claim is that the output is the same as before, byte for byte. TestGhosttyScrollbackTextMatchesTheLines holds it to that. It writes 3000 lines in ten shapes: a red line that ends in spaces, wide characters, a blank line, a line longer than the screen, a tab and an accent, an OSC 8 link that ends in spaces, a background carried onto the next row, a reversed space before plain text, a coloured directory name, and a plain line. Then 30 blank lines. It reads every line the old way and compares each with the new text. It also fails if the formatter path was not used at all, which would let the slow loop pass the test without anyone noticing.

Both checks have negative controls in the commit. With the styled-row check cut, this test and TestPlainCaptureMatchesLineByLine fail. With the hyperlink check cut, this test fails.

TestWaitForOutputDoesNotSlowFlood with -tags ghostty: 197.6 times before, 1.15 times after.

The other readers that went cell by cell

The wait was the loudest reader of the history. It was not the only one.

CopyScrollback lets a reader copy history lines under the lock and decode them after it. The history save and the packed snapshot use it. On the ghostty backend there was no cheap copy, so it read every line one cell at a time under the lock. For 1000 rows of 200 columns that cost about 50 ms and 40 MB. TestHistoryCaptureBudget allows 4 MB.

8c77ef57 has the library write a snapshot of the terminal under the lock instead, about 1 ms and 0.4 MB for that history, and copies the palette with it. The copy decodes the snapshot and reads its lines on first use, after the lock is released. TestHistoryCaptureBudget with -tags ghostty went from 38.4 MB to 2.4 MB. TestGhosttyScrollbackCopyMatchesTheLiveRead compares the copy with a live read on both screens, and fails when the copied palette loses an OSC 4 colour.

The render loop had the same problem in a smaller form. The link work the same day made the cell loop ask the emulator whether each row soft-wraps. On the ghostty backend each answer costs about five allocations, and a focused 207x55 frame went from 380 allocations to 648. TestRenderTerminalAllocationsDoNotScaleWithCells allows 600, and it failed. c9801f0e asks only on a line that has a URL to find. The frame came back to 389.

What I take from it

The fix for the wait was right, and it was measured. It was measured on one backend. The first number, 3.27 times, was the cost of looking too often. The second, 197.6 times, was the cost of one look on a backend that an earlier fix had left out on purpose, with a line in docs/perf.md that said so.

The two numbers came from the same test. Nothing about the test changed between them, only the build tag. A budget test that runs on one backend is a budget for one backend. The ghostty-vt workflow runs every package whose tests link internal/vt with -tags ghostty, internal/session among them. This is the kind of bug it is there for.