lanework/RENDER-INSTRUMENTATION.md

Render Instrumentation

How to find out why the board is slow, and how to prove it stopped being slow. Everything here is DEBUG-only and observes without branching: a release build carries none of it, and a debug build behaves identically with or without an Instruments trace attached.

Two instruments, both ported from the pathfinder's perf work and extended for Lanework's three body levels.

The counters — Kanban/UI/Board/BoardRenderMetrics.swift, a flat bag of static vars incremented at the top of BoardView.body, LaneView.body, TrashLaneView.body, CardFaceView.body, and inside MasonryLayout's measurement cache. Read from tests (KanbanTests/BoardRenderPerformanceTests.swift), never from the app. They answer "how many bodies ran", which is the question every equatable gate is a claim about and the one no profiler answers directly.

The signposts — Kanban/UI/Board/DragSignposts.swift, OSSignposter intervals on the drag hot path, subsystem dev.rzen.indie.Kanban, category drag. They answer "how long did the release take, and where did it go", which no counter answers.

The counters

Counter	Site
stripBodyEvaluations	BoardView.body
laneBodyEvaluations	LaneView.body
trashLaneBodyEvaluations	TrashLaneView.body
containerBodyEvaluations	the two above, summed — what the budgets are written against
cardBodyEvaluations	CardFaceView.body, both homes
masonrySizeThatFitsCalls / masonryPlaceCalls	MasonryLayout's two Layout callbacks
masonryMeasurements / masonryCacheHits	the two halves of its measurement cache

The strip counter is the one the pathfinder does not have, and it is the discriminator. "A lane re-ran" means two completely different things depending on whether the strip re-ran with it:

• strip and lanes — a parent pass whose .equatable() gate did not suppress. Look at LaneView.==.
• lanes without the strip — a direct Observation invalidation. No gate has any say over one of those (LaneView.=='s own doc comment is explicit), so the fix is to stop the body reading whatever moved.

What the first run found (2026-08-01)

Measured on a hosted board of 6 lanes × 30 cards, and again at 12 lanes × 15:

Step	strip	containers	cards
first paint	1	12	540
reload, nothing changed	1	0	0
reload, ONE card edited	2	6 (= lanes)	1 of 180
the same, on a 12-lane board	2	12 (= lanes)	1 of 180
select one card	1	6	180 of 180

Three readings.

The value-equal skip works, and the lane gate works with it. A reload that found nothing changed re-runs the strip once — BoardView watches store.landedReloads, which moves on every landing — and zero lanes and cards. That is LaneView.== suppressing a real parent pass, and it is the sharpest single piece of evidence that the gate is wired correctly.

The card gate works. One card edited on disk costs one CardFaceView.body out of 180, on both board widths. Un-gated it would be all 180.

The lane gate is never asked on a snapshot change, and that is a live finding. A one-card edit costs one lane body per lane on the board — 6 of 6, 12 of 12. It is not the comparison: BoardRenderPerformanceTests.theLaneCostFollowsTheBoard pins that an untouched sibling lane comes back from the reload as an equal Lane value, with every other member of LaneView.== a window-lived constant. The cause is a read:

LaneView.body → header → .boardTextInk(headerInk) → headerInk
    → BoardTextInk.scheme(forBoardBackground: store.snapshot.background, appearance:)

Observation tracks whole properties. Reading .background off store.snapshot subscribes that body to the entire snapshot, so a reload that changes one card anywhere invalidates every lane on the board directly — and .equatable() has no say over a direct invalidation. The fix is to resolve the board's ink once in BoardView and pass it down as a compared parameter, the way slotWidth and columns already are. Until then the container budget in the test is written to the number the tree actually produces, with the reason, and theLaneCostFollowsTheBoard is a tripwire in both directions: it fails if the number goes down, which is the fix landing.

Selection is O(board) in card bodies. Selecting one card re-runs all 180 faces, because CardFaceView.body reads store.selection through isSelected. This is the Observation half the gates explicitly do not cover, and narrowing it would mean each face taking its own selected-ness as a compared parameter — a design change, not a gate.

The signposts

Signpost	Span	Emitted from
drop-updated	one dropUpdated(info:), retarget and returned DropProposal alike	LaneDropDelegate, StripDropDelegate, TrashDropDelegate
retarget-cards	one BoardDropContext.retargetCards(inLane:) — resting layout plus DropSlotMath.cardSlot	BoardDrops.swift
drop-commit	one BoardDropContext.commitDrop(), every refusing branch included	BoardDrops.swift
drop-release-pause	DragSession.commit(into:) → the snapshot that retires the hold	DragSession.swift
drag-input-latency	an event, once per dropUpdated	DragSignposts.sampleInput()

drop-release-pause is the number a user calls "the board freezes when I let go". It ends with an outcome:

• echo — the covering snapshot landed (DragSession.handOff). The healthy case; the duration is the echo reload's latency.
• timeout — CommittedHold.timeout fired first (DragSession.expire). The write did not come back, and the board animated the arrangement back to snapshot order. A timeout in a trace is a bug, not a slow frame.
• cleared — any other teardown (the watchdog, a cancel, a second drag beginning).
• superseded — a begin found one already open. Should never appear.

It begins at commit(into:) rather than at commitDrop()'s first line because that is the only path that arms a hold: every begin therefore has an end, and a refused release opens nothing. The guards above it are inside drop-commit, which wraps the whole function.

The three retargeting delegates are instrumented, BoardFallbackDropDelegate is not — it retargets nothing, so a span around it would time an early return. Single-target dispatch means exactly one delegate sees any one event, so the drop-updated intervals never overlap and drag-input-latency's cadence is never double-counted.

Input latency, and the honest gap

drag-input-latency wants now − (the time the OS stamped the mouse event). The SwiftUI drop path never surfaces that stamp. DropInfo carries a location and item providers and nothing else. NSDraggingInfo underneath it carries a dragging sequence number, a location and a pasteboard — no timestamp. And Lanework's own drop code reads only static NSEvent class properties (mouseLocation, modifierFlags, pressedMouseButtons), never an NSEvent instance, by design (BoardDropContext.globalCursor, DRAG-REORDER.md § Animation-proof inputs). There is no event object in hand to ask.

So the probe samples the one base that can exist — NSApp.currentEvent — and says which base it got rather than inventing one:

• base=event latencyMs=… — a mouse event was current. NSEvent.timestamp and CACurrentMediaTime() are both seconds since boot off mach_absolute_time, so the subtraction is unit-consistent and this is the real figure.
• base=none latencyMs=-1 — no mouse event was current (a drag driven entirely by the drag server, a Finder file drag with no local event). Only sinceLastMs is meaningful there: it is the callback cadence, which is what a laggy drag actually degrades, and it is not latency. Do not read the trace as though it were.

Both cases always carry sinceLastMs, reset at DragSession.begin so a drag's first sample is not the gap since the previous drag's last one.

Reading a trace

Instruments 26's SwiftUI template (WWDC25 session 306)

⌘I from Xcode, choose SwiftUI. Four lanes matter:

• Update Groups — one row per SwiftUI update, with the cause on the left and the work on the right. This is where a drag that costs one update per mouse sample looks different from one that costs three.
• Long View Body Updates — bodies that took longer than the threshold. Anything from LaneView or CardFaceView here is a body that should have been gated; cross-reference against the counters above, which say how many ran where this says how long one took.
• Long Representable Updates and Other Long Updates — AppKit bridges and everything else. NSHostingView, the toolbar's NSSearchToolbarItem, the window controller.
• Cause & Effect Graph — select an update and Instruments draws the chain: Gesture → State Change → View Body Update. For a drag this should read drop-updated → DragSession.propose → one lane's body. If it reads → every lane's body, that is the headerInk finding above, and the graph names the property.

Add the os_signpost instrument to the same trace so drop-release-pause sits on the same timeline as the update groups it brackets. That pairing is the whole point: a long pause with no update groups inside it is waiting on the write, a long pause full of them is the board re-rendering.

The Hitches instrument

Supported on macOS. It splits a dropped frame two ways, and the split is the diagnosis:

• commit hitch — the app took too long to produce the frame (body evaluation, layout, the write bracket). Ours to fix, and the counters are how.
• render hitch — the render server took too long. Usually offscreen passes, blurs, and shadow rasterisation; not a body-count problem.

Thresholds, as hitch-time-ratio in ms of hitch per second of scrolling or animation:

| ≤ 10 ms/s | good | | ≤ 25 ms/s | warning | | ≤ 50 ms/s | critical |

A drag that reads clean on the counters and still hitches is a render hitch, and the next place to look is the lane plate's translucency and the drag replica's shadow, not LaneView.==.

log show and the sample trigger

The technique from the 2026-07-31 stall hunt, for the case where the stall is not reproducible under Instruments. The signposts land in the unified log, so they can be read after the fact with no trace attached:

# everything the drag emitted in the last two minutes, newest last
/usr/bin/log show --last 2m --style compact \
  --predicate 'subsystem == "dev.rzen.indie.Kanban" && category == "drag"'

And to catch a stall while it is happening — stream the log, and shell out to sample the moment a release pause opens:

/usr/bin/log stream --style compact \
  --predicate 'subsystem == "dev.rzen.indie.Kanban" && category == "drag"' \
| while read -r line; do
    case "$line" in
      *drop-release-pause*) /usr/bin/sample Lanework 3 -file /tmp/lanework-release.txt & ;;
    esac
  done

Three seconds of backtraces starting at the release. If the pause was the write, the main thread is in BoardWriter; if it was the reload, it is in BoardLoader on a detached task and the main thread is idle; if it was rendering, it is in AG::Graph under NSHostingView. That three-way split is what the signpost alone cannot tell you, and it is why the trigger is worth the shell loop.

Running the counters

xcodebuild -project Kanban.xcodeproj -scheme Kanban \
  -destination 'platform=macOS,arch=arm64' \
  -only-testing:KanbanTests/BoardRenderPerformanceTests test

The suite prints a line per step (── reload, ONE card edited — …) whatever the outcome, so a run can be compared against a previous one. Only the invariants fail it; absolute figures are machine facts and are not asserted.

It hosts the whole BoardView in a 1600×1000 off-screen NSWindow, with a real AppModel whose registry file and clipboard staging are redirected into the test's own temp folder. Not a stand-in for the strip: the gates exist because BoardView's body re-runs for reasons that have nothing to do with any one lane, and a harness that hosted LaneView directly would be asserting about a parent that does not exist. Bodies only run when a display pass is forced, so the harness pumps the run loop and calls layoutSubtreeIfNeeded / displayIfNeeded several times per step — an update scheduled by the previous flush needs another turn.