# 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 var`s 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:

```sh
# 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:

```sh
/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

```sh
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.