perf(diagnostics): trace tab switches and benchmark launch, table open and tab switch

apple/CONTRIBUTING.md

@@ -94,6 +94,10 @@ xcodebuild -project TableProMobile/TableProMobile.xcodeproj -scheme TableProMobi
     -destination 'platform=iOS Simulator,name=<iPhone>' -parallel-testing-enabled NO -skipPackagePluginValidation CODE_SIGNING_ALLOWED=NO ARCHS=arm64
 ```
 
+## Performance
+
+`scripts/benchmark-app-paths.sh` times cold launch, opening a 1,000,000-row table and switching tabs, 10 runs each, and checks the median and 95th percentile against the budgets in `scripts/benchmark/app-paths/baseline.json`. Usage, permissions and the fixtures are in its header. In Instruments the same three paths are the `AppLaunch`, `TableLoad` and `TabSwitch` intervals under Points of Interest.
+
 ## Code style
 
 `.swiftlint.yml` is the source of truth. Run `swiftlint lint --strict <changed .swift files>`; CI lints all of `apple/` the same way on every pull request, and nothing lints during an Xcode build. Formatting the linter leaves to you:

apple/TablePro/Core/Diagnostics/LaunchTracer.swift

@@ -83,9 +83,10 @@ internal final class LaunchTracer {
         var lines = ["launch trace (ms since exec)"]
         var previous: TimeInterval = 0
         for mark in marks {
+            // String(format:) ignores the width of a %@ argument, so the name is padded here.
             lines.append(String(
-                format: "  %-26@ %8.1f  (+%6.1f)",
-                mark.stage.rawValue as NSString,
+                format: "  %@ %8.1f  (+%6.1f)",
+                mark.stage.rawValue.padding(toLength: 26, withPad: " ", startingAt: 0),
                 mark.offset * 1_000,
                 (mark.offset - previous) * 1_000
             ))

apple/TablePro/Core/Diagnostics/TabSwitchTrace.swift

@@ -0,0 +1,200 @@
+//
+//  TabSwitchTrace.swift
+//  TablePro
+//
+
+import Foundation
+
+internal enum TabSwitchTrigger: String, Sendable {
+    case adjacentTab
+    case tabNumber
+    case recentTab
+    case tabStrip
+}
+
+// requery: the memory budget dropped the rows. firstLoad: restored from the last session, never shown since.
+internal enum TabSwitchRows: String, Sendable {
+    case resident
+    case requery
+    case firstLoad
+
+    init(loads: Bool, needsReload: Bool) {
+        guard loads else {
+            self = .resident
+            return
+        }
+        self = needsReload ? .requery : .firstLoad
+    }
+}
+
+internal enum TabSwitchOutcome: String, Sendable {
+    case presented
+    case superseded
+    case loadFailed
+}
+
+internal struct TabSwitchTiming: Equatable, Sendable {
+    let sequence: Int
+    let trigger: TabSwitchTrigger
+    let rows: TabSwitchRows
+    let outcome: TabSwitchOutcome
+    let total: Duration
+    let selection: Duration
+
+    var reportLine: String {
+        """
+        tabswitch #\(sequence) trigger=\(trigger.rawValue) rows=\(rows.rawValue) \
+        outcome=\(outcome.rawValue) totalMs=\(Self.milliseconds(total)) \
+        selectionMs=\(Self.milliseconds(selection))
+        """
+    }
+
+    private static func milliseconds(_ duration: Duration) -> String {
+        String(format: "%.1f", TableLoadDuration.milliseconds(duration))
+    }
+}
+
+// One switch at a time: a second request means the user moved on, so the first ends as superseded.
+internal struct TabSwitchTraceRecorder {
+    internal enum Ending: Equatable {
+        case timed(TabSwitchTiming)
+        case abandoned(sequence: Int)
+    }
+
+    internal enum SelectionResult: Equatable {
+        case ignored
+        case started(sequence: Int)
+        case abandoned(sequence: Int)
+        case ended(TabSwitchTiming)
+    }
+
+    internal enum RowsResult: Equatable {
+        case ignored
+        case awaitFrame(sequence: Int)
+        case ended(TabSwitchTiming)
+    }
+
+    // A selection landing this long after the request came from something other than the gesture.
+    internal static let requestExpiry = Duration.seconds(1)
+
+    internal static let maximumEventAge: TimeInterval = 2
+
+    private struct Selection {
+        let rows: TabSwitchRows
+        let at: ContinuousClock.Instant
+        var awaitingRows: Bool
+    }
+
+    private struct Trace {
+        let sequence: Int
+        let trigger: TabSwitchTrigger
+        let tabId: UUID
+        let startedAt: ContinuousClock.Instant
+        let requestedAt: ContinuousClock.Instant
+        var selection: Selection?
+    }
+
+    private var current: Trace?
+    private var nextSequence = 1
+
+    internal init() {}
+
+    internal var isAwaitingPresentation: Bool {
+        current?.selection != nil
+    }
+
+    // NSEvent.timestamp and systemUptime share mach_absolute_time, so the difference is the event's age.
+    internal static func startInstant(
+        eventTimestamp: TimeInterval?,
+        uptime: TimeInterval,
+        now: ContinuousClock.Instant
+    ) -> ContinuousClock.Instant {
+        guard let eventTimestamp else { return now }
+        let age = uptime - eventTimestamp
+        guard age >= 0, age <= maximumEventAge else { return now }
+        return now.advanced(by: .seconds(-age))
+    }
+
+    internal mutating func request(
+        _ trigger: TabSwitchTrigger,
+        to tabId: UUID,
+        startedAt: ContinuousClock.Instant,
+        at now: ContinuousClock.Instant
+    ) -> (sequence: Int, previous: Ending?) {
+        let previous = current.map { end($0, as: .superseded, at: now) }
+        let sequence = nextSequence
+        nextSequence += 1
+        current = Trace(sequence: sequence, trigger: trigger, tabId: tabId, startedAt: startedAt, requestedAt: now)
+        return (sequence, previous)
+    }
+
+    internal mutating func applySelection(
+        tabId: UUID,
+        rows: TabSwitchRows,
+        at now: ContinuousClock.Instant
+    ) -> SelectionResult {
+        guard var trace = current else { return .ignored }
+        if let selection = trace.selection {
+            // The user moved on, through a path that asks for no switch of its own, such as the sidebar.
+            guard tabId != trace.tabId else { return .ignored }
+            current = nil
+            return .ended(timing(trace, selection, outcome: .superseded, at: now))
+        }
+        guard trace.tabId == tabId else { return .ignored }
+        guard trace.requestedAt.duration(to: now) <= Self.requestExpiry else {
+            current = nil
+            return .abandoned(sequence: trace.sequence)
+        }
+        trace.selection = Selection(rows: rows, at: now, awaitingRows: rows != .resident)
+        current = trace
+        return .started(sequence: trace.sequence)
+    }
+
+    internal mutating func rowsLoaded(tabId: UUID, completed: Bool, at now: ContinuousClock.Instant) -> RowsResult {
+        guard var trace = current, trace.tabId == tabId, var selection = trace.selection, selection.awaitingRows
+        else { return .ignored }
+        guard completed else {
+            current = nil
+            return .ended(timing(trace, selection, outcome: .loadFailed, at: now))
+        }
+        selection.awaitingRows = false
+        trace.selection = selection
+        current = trace
+        return .awaitFrame(sequence: trace.sequence)
+    }
+
+    internal mutating func supersede(sequence: Int, at now: ContinuousClock.Instant) -> Ending? {
+        guard let trace = current, trace.sequence == sequence else { return nil }
+        current = nil
+        return end(trace, as: .superseded, at: now)
+    }
+
+    internal mutating func framePresented(sequence: Int, at now: ContinuousClock.Instant) -> TabSwitchTiming? {
+        guard let trace = current, trace.sequence == sequence,
+              let selection = trace.selection, !selection.awaitingRows
+        else { return nil }
+        current = nil
+        return timing(trace, selection, outcome: .presented, at: now)
+    }
+
+    private func end(_ trace: Trace, as outcome: TabSwitchOutcome, at now: ContinuousClock.Instant) -> Ending {
+        guard let selection = trace.selection else { return .abandoned(sequence: trace.sequence) }
+        return .timed(timing(trace, selection, outcome: outcome, at: now))
+    }
+
+    private func timing(
+        _ trace: Trace,
+        _ selection: Selection,
+        outcome: TabSwitchOutcome,
+        at now: ContinuousClock.Instant
+    ) -> TabSwitchTiming {
+        TabSwitchTiming(
+            sequence: trace.sequence,
+            trigger: trace.trigger,
+            rows: selection.rows,
+            outcome: outcome,
+            total: trace.startedAt.duration(to: now),
+            selection: trace.startedAt.duration(to: selection.at)
+        )
+    }
+}

apple/TablePro/Core/Diagnostics/TabSwitchTracer.swift

@@ -0,0 +1,128 @@
+//
+//  TabSwitchTracer.swift
+//  TablePro
+//
+
+import AppKit
+import os
+
+// Key press or click to the first frame of the new tab; a tab that re-queries ends after its rows are drawn.
+@MainActor
+internal final class TabSwitchTracer {
+    internal static let shared = TabSwitchTracer()
+
+    nonisolated private static let writesToStandardError =
+        ProcessInfo.processInfo.environment["TABLEPRO_TAB_SWITCH_TRACE"] == "1"
+
+    private static let inputEventTypes: Set<NSEvent.EventType> = [
+        .keyDown, .keyUp, .flagsChanged,
+        .leftMouseDown, .leftMouseUp, .rightMouseDown, .rightMouseUp, .otherMouseDown, .otherMouseUp
+    ]
+
+    private let logger = Logger(subsystem: "com.TablePro", category: "TabSwitch")
+    private let signposter = OSSignposter(subsystem: "com.TablePro", category: .pointsOfInterest)
+    private let clock = ContinuousClock()
+    private var recorder = TabSwitchTraceRecorder()
+    private var intervals: [Int: OSSignpostIntervalState] = [:]
+    private weak var window: NSWindow?
+    private var isShowing: (@MainActor () -> Bool)?
+
+    internal func requestSwitch(
+        _ trigger: TabSwitchTrigger,
+        to tabId: UUID,
+        event: NSEvent? = NSApp.currentEvent
+    ) {
+        let now = clock.now
+        let timestamp = event.flatMap { Self.inputEventTypes.contains($0.type) ? $0.timestamp : nil }
+        let startedAt = TabSwitchTraceRecorder.startInstant(
+            eventTimestamp: timestamp,
+            uptime: ProcessInfo.processInfo.systemUptime,
+            now: now
+        )
+        let (sequence, previous) = recorder.request(trigger, to: tabId, startedAt: startedAt, at: now)
+        if let previous {
+            end(previous)
+        }
+        intervals[sequence] = signposter.beginInterval(
+            "TabSwitch",
+            id: signposter.makeSignpostID(),
+            "#\(sequence, privacy: .public) \(trigger.rawValue, privacy: .public)"
+        )
+    }
+
+    // isShowing answers, when the frame comes, whether the window still shows that tab.
+    internal func selectionApplied(
+        tabId: UUID,
+        rows: TabSwitchRows,
+        window: NSWindow?,
+        isShowing: @escaping @MainActor () -> Bool
+    ) {
+        // Another window's selection does not move the switch this one is showing.
+        if recorder.isAwaitingPresentation, window !== self.window { return }
+        switch recorder.applySelection(tabId: tabId, rows: rows, at: clock.now) {
+        case .ignored:
+            return
+        case .abandoned(let sequence):
+            end(.abandoned(sequence: sequence))
+        case .ended(let timing):
+            end(.timed(timing))
+        case .started(let sequence):
+            self.window = window
+            self.isShowing = isShowing
+            logger.debug("tabswitch #\(sequence) selected rows=\(rows.rawValue, privacy: .public)")
+            guard rows == .resident else { return }
+            awaitFrame(sequence)
+        }
+    }
+
+    internal func tableLoadFinished(tabId: UUID, outcome: TableLoadOutcome) {
+        switch recorder.rowsLoaded(tabId: tabId, completed: outcome == .completed, at: clock.now) {
+        case .ignored:
+            return
+        case .awaitFrame(let sequence):
+            awaitFrame(sequence)
+        case .ended(let timing):
+            end(.timed(timing))
+        }
+    }
+
+    private func awaitFrame(_ sequence: Int) {
+        guard let window else {
+            framePresented(sequence)
+            return
+        }
+        window.afterNextFrame { [weak self] in
+            self?.framePresented(sequence)
+        }
+    }
+
+    // A connection switch or a sidebar click can leave the tab while its rows load, with no selection change here.
+    private func framePresented(_ sequence: Int) {
+        guard isShowing?() ?? true else {
+            if let ending = recorder.supersede(sequence: sequence, at: clock.now) {
+                end(ending)
+            }
+            return
+        }
+        guard let timing = recorder.framePresented(sequence: sequence, at: clock.now) else { return }
+        end(.timed(timing))
+    }
+
+    private func end(_ ending: TabSwitchTraceRecorder.Ending) {
+        switch ending {
+        case .abandoned(let sequence):
+            endInterval(sequence, outcome: "abandoned")
+        case .timed(let timing):
+            let line = timing.reportLine
+            logger.debug("\(line, privacy: .public)")
+            endInterval(timing.sequence, outcome: timing.outcome.rawValue)
+            guard Self.writesToStandardError else { return }
+            FileHandle.standardError.write(Data("\(line)\n".utf8))
+        }
+    }
+
+    private func endInterval(_ sequence: Int, outcome: String) {
+        guard let interval = intervals.removeValue(forKey: sequence) else { return }
+        signposter.endInterval("TabSwitch", interval, "\(outcome, privacy: .public)")
+    }
+}

apple/TablePro/Core/Diagnostics/TableLoadTracer.swift

@@ -172,6 +172,7 @@ internal final class TableLoadTracer {
     /// error's Swift type name still reaches a developer reading `log stream`, while the recorded
     /// outcome stays a closed set an external report can group by.
     internal func finish(token: TableLoadTraceToken, outcome: TableLoadOutcome, detail: String? = nil) {
+        let ownsTab = recorder.activeToken(for: token.tabId) == token
         guard let timing = recorder.finish(token: token, outcome: outcome, at: clock.now) else { return }
         let label = Self.label(for: outcome, detail: detail)
         logger.debug(
@@ -183,6 +184,9 @@ internal final class TableLoadTracer {
         )
         endInterval(for: timing.token, outcome: label)
         drainCompletedTraces()
+        // A superseded load ending late says nothing about the rows the tab now waits for.
+        guard ownsTab else { return }
+        TabSwitchTracer.shared.tableLoadFinished(tabId: timing.token.tabId, outcome: outcome)
     }
 
     private static func label(for outcome: TableLoadOutcome, detail: String?) -> String {