Files
lanework/Kanban/UI/Board/DragSignposts.swift
rzen 0218ae4c21 Drag instrumentation — render counters, hot-path signposts, and the invariants that prove the gates
BoardRenderMetrics (DEBUG-only, the pathfinder's counter bag plus a
strip-body discriminator that tells a failed gate from a direct
Observation invalidation) counted at BoardView/LaneView/CardFaceView/
TrashLaneView bodies and MasonryLayout's callbacks. DragSignposts wraps
dropUpdated, retargetCards, commitDrop, and the commit-to-covering-
snapshot release pause; input latency reports honestly against
NSApp.currentEvent's mach base or labels itself base=none — no event
timestamp rides the drop path. BoardRenderPerformanceTests hosts the
real BoardView off-screen: a value-equal reload runs zero lane and zero
card bodies, a one-card edit repaints one card of 180. The lane-body
budget is <= laneCount with the headerInk chain documented and a
two-way tripwire that fails when the fix lands. Methodology in
RENDER-INSTRUMENTATION.md. Release build proves it all compiles out.

Drag-perf card a450ad09.

Claude-Session: https://claude.ai/code/session_01CqjXB7ASoWtbyoGod68k97
2026-08-01 20:04:01 -04:00

165 lines
8.3 KiB
Swift
Raw Permalink Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
#if DEBUG
import AppKit
import QuartzCore
import os.signpost
/// **The drag hot path, as `OSSignposter` intervals — DEBUG only, fire-and-forget, no branches.**
///
/// Three questions the 2026-07-31 drag-performance work left unmeasurable from inside the app, and
/// one it can only half-answer. Each is an interval on the `dev.rzen.indie.Kanban` subsystem's
/// `drag` category, so Instruments' os_signpost lane graphs them beside the SwiftUI template's
/// Update Groups and the Hitches instrument's commit/render split (RENDER-INSTRUMENTATION.md).
///
/// | Signpost | Span |
/// | --- | --- |
/// | `drop-updated` | one `dropUpdated(info:)` — the per-event retarget **and** the returned `DropProposal` |
/// | `retarget-cards` | one `BoardDropContext.retargetCards(inLane:)` — resting layout + `DropSlotMath.cardSlot` |
/// | `drop-commit` | one `BoardDropContext.commitDrop()` — the synchronous write bracket the release blocks on |
/// | `drop-release-pause` | the committed-overlay hold: `DragSession.commit(into:)` → the snapshot that retires it |
/// | `drag-input-latency` | *event*, not interval — see below |
///
/// ### The release pause, and why it begins where it does
///
/// `drop-release-pause` is the number a user calls "the board freezes when I let go": the write
/// goes out, the overlay keeps drawing the arrangement, and the shadows only dissolve when the echo
/// reload lands (`CommittedHold`, DRAG-REORDER.md § The committed-overlay hold). It therefore has to
/// span two callbacks — `performDrop` on one side, `BoardView`'s `snapshotGeneration` watch on the
/// other — which is the one span here that needs retained state rather than a `defer`.
///
/// It begins at `DragSession.commit(into:)` rather than at `commitDrop()`'s first line, deliberately:
/// `commit(into:)` is the *only* path that arms a hold, so every begin has an end, and a refused
/// release (a vanished lane, an emptied run, a mixed-kind trash drag) never opens an interval that
/// nothing would close. The handful of guards above it are covered by `drop-commit`, which wraps the
/// whole of `commitDrop()` including the branches that return `false`. The end carries an
/// `outcome` — `echo`, `timeout` (`DragSession.expire`) or `cleared` (any other teardown) — because a
/// pause that ended on the watchdog rather than on a snapshot is a different bug from a slow one.
///
/// ### Input latency: what is measurable, and the gap
///
/// "The shadow lags the cursor" 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, and no timestamp either; and Lanework's own drop code reads only *static*
/// `NSEvent` class properties (`mouseLocation`, `modifierFlags`, `pressedMouseButtons`) — never an
/// `NSEvent` instance (`BoardDropContext.globalCursor`). There is no event object in hand to ask.
///
/// So this samples the one base that can exist — `NSApp.currentEvent`, the event AppKit is currently
/// dispatching — and **says which base it got** rather than inventing one. `NSEvent.timestamp` and
/// `CACurrentMediaTime()` are both seconds since boot off `mach_absolute_time`, so where a mouse
/// event *is* current the subtraction is unit-consistent and is the real figure. Where it is not —
/// a drag driven entirely by the drag server, a Finder file drag with no local mouse event at all —
/// the emitted event says `base=none` and carries only `sinceLastMs`, the interval since the previous
/// sample. That number is honest (it is the callback cadence, which is what a laggy drag actually
/// degrades) and it is not latency; the trace must not be read as though it were.
///
/// ### Strict concurrency
///
/// `OSSignposter` is `Sendable` and its `emit`/`beginInterval`/`endInterval` are safe from anywhere.
/// The one piece of retained state — the open release interval — lives on the main actor, which is
/// where every caller already is (drop delegates, `DragSession`, `BoardView`'s `onChange`).
@MainActor
enum DragSignposts {
/// The subsystem every `Logger` in this app already uses, so a trace and a log line filter the
/// same way. `category: "drag"` keeps the intervals out of the store's and the window's noise.
static let signposter = OSSignposter(subsystem: "dev.rzen.indie.Kanban", category: "drag")
// MARK: - Per-event spans
/// `dropUpdated(info:)` — the whole callback, retarget and proposal alike.
///
/// Returned rather than scoped, so the call site can pair it with a `defer` and leave the
/// existing early returns exactly as they are.
static func beginDropUpdated() -> OSSignpostIntervalState {
signposter.beginInterval("drop-updated", id: .exclusive)
}
static func endDropUpdated(_ state: OSSignpostIntervalState) {
signposter.endInterval("drop-updated", state)
}
static func beginRetargetCards() -> OSSignpostIntervalState {
signposter.beginInterval("retarget-cards", id: .exclusive)
}
static func endRetargetCards(_ state: OSSignpostIntervalState) {
signposter.endInterval("retarget-cards", state)
}
static func beginCommitDrop() -> OSSignpostIntervalState {
signposter.beginInterval("drop-commit", id: .exclusive)
}
static func endCommitDrop(_ state: OSSignpostIntervalState) {
signposter.endInterval("drop-commit", state)
}
// MARK: - The release pause
/// The open `drop-release-pause` interval, or `nil` when no hold is standing.
///
/// One at a time by construction: `DragSession` holds one `CommittedHold` and a second drag
/// cannot begin while it stands. A begin that finds one open closes it as `superseded` anyway,
/// so a mismatched pair can never leak an interval that never ends.
private static var releasePause: OSSignpostIntervalState?
/// The write is out and the committed overlay is holding — the pause has started.
static func beginReleasePause() {
if releasePause != nil { endReleasePause(outcome: "superseded") }
releasePause = signposter.beginInterval("drop-release-pause", id: .exclusive)
}
/// The overlay dissolved. `outcome` distinguishes the snapshot landing from the two ways a hold
/// can end without one.
static func endReleasePause(outcome: StaticString) {
guard let state = releasePause else { return }
releasePause = nil
signposter.endInterval("drop-release-pause", state, "\(outcome)")
}
// MARK: - Input latency
/// When the previous `dropUpdated` sample was taken — the fallback figure's base, and the only
/// one that is available unconditionally.
private static var lastSample: CFTimeInterval?
/// Emits one `drag-input-latency` event per drop callback.
///
/// See the type's note for why this is best-effort: `base=event` is a true input-to-callback
/// latency, `base=none` is a cadence sample wearing the same name, and the emitted field says
/// which. Nothing here is retained beyond one `CFTimeInterval` and nothing branches on it.
static func sampleInput() {
let now = CACurrentMediaTime()
let sinceLast = lastSample.map { (now - $0) * 1000 } ?? -1
lastSample = now
let event = NSApp.currentEvent
let stamp: CFTimeInterval? = switch event?.type {
case .some(.mouseMoved), .some(.leftMouseDragged), .some(.rightMouseDragged),
.some(.otherMouseDragged), .some(.leftMouseUp), .some(.leftMouseDown):
event?.timestamp
default:
nil
}
if let stamp {
signposter.emitEvent(
"drag-input-latency", id: .exclusive,
"base=event latencyMs=\((now - stamp) * 1000, privacy: .public) sinceLastMs=\(sinceLast, privacy: .public)"
)
} else {
signposter.emitEvent(
"drag-input-latency", id: .exclusive,
"base=none latencyMs=-1 sinceLastMs=\(sinceLast, privacy: .public)"
)
}
}
/// Forgets the cadence base — a new drag's first sample must not report the gap since the
/// previous drag's last one.
static func resetInputSampling() {
lastSample = nil
}
}
#endif