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
This commit is contained in:
@@ -0,0 +1,164 @@
|
||||
#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
|
||||
Reference in New Issue
Block a user