diff --git a/desktop/macos/Desktop/Sources/AnalyticsManager.swift b/desktop/macos/Desktop/Sources/AnalyticsManager.swift index 4f1ea4c4559..06cc85d04ae 100644 --- a/desktop/macos/Desktop/Sources/AnalyticsManager.swift +++ b/desktop/macos/Desktop/Sources/AnalyticsManager.swift @@ -559,23 +559,46 @@ class AnalyticsManager { PostHogManager.shared.appLaunched() } + /// A process reports startup once. `ViewModelContainer.loadAllData()` runs + /// again after an owner switch, and that second run is not a launch. + private var didReportStartupTiming = false + + /// Report one launch's startup timing. + /// + /// - `dataLoadMs` is the critical startup path inside `loadAllData()`. This is + /// what the old `time_to_interactive_ms` actually measured, which is why it + /// reported 11–131ms for a "cold start". + /// - `timeToInteractiveMs` is measured from the kernel's process-start stamp, + /// so it includes dyld, `main`, and everything before the data load. It is + /// omitted rather than faked when the kernel lookup fails. func trackStartupTiming( - dbInitMs: Double, timeToInteractiveMs: Double, hadUncleanShutdown: Bool, - databaseInitFailed: Bool + dbInitMs: Double, dataLoadMs: Double, hadUncleanShutdown: Bool, + databaseInitFailed: Bool, + timeToInteractiveMs: Double? = AppStartupTiming.millisecondsSinceProcessStart() ) { guard !Self.isDevBuild else { return } - // Routed to Sentry as a breadcrumb (perf telemetry, not product analytics) so the data - // is attached to any same-session crash report without creating a per-launch analytics - // event. If we ever need real perf metrics, wire up SentrySDK.startTransaction here. - let breadcrumb = Breadcrumb(level: .info, category: "app.startup") - breadcrumb.message = "App Startup Timing" - breadcrumb.data = [ + guard !didReportStartupTiming else { return } + didReportStartupTiming = true + + var properties: [String: Any] = [ "db_init_ms": round(dbInitMs), - "time_to_interactive_ms": round(timeToInteractiveMs), + "data_load_ms": round(dataLoadMs), "had_unclean_shutdown": hadUncleanShutdown, "database_init_failed": databaseInitFailed, ] + if let timeToInteractiveMs { + properties["time_to_interactive_ms"] = round(timeToInteractiveMs) + } + + // Also a Sentry breadcrumb so the numbers stay attached to a same-session + // crash report. Sentry is a per-issue view; it cannot answer "is startup + // getting slower across the fleet", which is why this is in PostHog too. + let breadcrumb = Breadcrumb(level: .info, category: "app.startup") + breadcrumb.message = "App Startup Timing" + breadcrumb.data = properties SentrySDK.addBreadcrumb(breadcrumb) + + PostHogManager.shared.track("App Startup Timing", properties: properties) } /// Track first launch with comprehensive system diagnostics diff --git a/desktop/macos/Desktop/Sources/Observability/AppStartupTiming.swift b/desktop/macos/Desktop/Sources/Observability/AppStartupTiming.swift new file mode 100644 index 00000000000..1450b51bc52 --- /dev/null +++ b/desktop/macos/Desktop/Sources/Observability/AppStartupTiming.swift @@ -0,0 +1,46 @@ +import Darwin +import Foundation + +/// Wall-clock start of this process, read from the kernel process table. +/// +/// `App Startup Timing` reported `time_to_interactive_ms` values of 11–131ms, +/// which is not a cold start of a SwiftUI app — it was the duration of +/// `ViewModelContainer.loadAllData()`, which begins long after `main()`. The +/// only honest source for "when did this process actually start" is +/// `kinfo_proc.kp_proc.p_starttime`, which the kernel stamps at exec, before +/// dyld, before `main`, and before any code of ours could take a timestamp. +enum AppStartupTiming { + /// Wall-clock start of `pid` as recorded by the kernel, or nil when the + /// sysctl is unavailable. + static func processStartDate(pid: pid_t = getpid()) -> Date? { + var mib: [Int32] = [CTL_KERN, KERN_PROC, KERN_PROC_PID, pid] + var info = kinfo_proc() + var size = MemoryLayout.stride + let result = sysctl(&mib, UInt32(mib.count), &info, &size, nil, 0) + guard result == 0, size > 0 else { return nil } + let started = info.kp_proc.p_starttime + guard started.tv_sec > 0 else { return nil } + return Date( + timeIntervalSince1970: Double(started.tv_sec) + Double(started.tv_usec) / 1_000_000) + } + + /// Milliseconds between two instants, floored at zero. + /// + /// The process-start stamp and `Date()` both come from the wall clock, so a + /// clock adjustment between them can produce a negative or absurd interval. + /// A startup metric must never report a negative duration. + static func elapsedMilliseconds(from start: Date, to end: Date) -> Double { + max(0, end.timeIntervalSince(start) * 1_000) + } + + /// Milliseconds from process start to `now`, or nil when the process start is + /// unavailable. Callers omit the property rather than substituting a + /// plausible-looking number. + static func millisecondsSinceProcessStart( + now: Date = Date(), + processStart: Date? = AppStartupTiming.processStartDate() + ) -> Double? { + guard let processStart else { return nil } + return elapsedMilliseconds(from: processStart, to: now) + } +} diff --git a/desktop/macos/Desktop/Sources/Rewind/Core/RewindDatabase.swift b/desktop/macos/Desktop/Sources/Rewind/Core/RewindDatabase.swift index f8d56c3aa93..43aed6c0ecb 100644 --- a/desktop/macos/Desktop/Sources/Rewind/Core/RewindDatabase.swift +++ b/desktop/macos/Desktop/Sources/Rewind/Core/RewindDatabase.swift @@ -23,6 +23,14 @@ actor RewindDatabase { /// Path to the running flag file (used to detect unclean shutdown) private var runningFlagPath: String? + /// Whether the *previous* session ended uncleanly, latched at the first + /// observation in this process. `.omi_running` is created at the end of + /// `performInitialization()`, so the answer stops being observable once the + /// database opens — and any of the lazily-initializing storage actors can get + /// there first. That race is why `App Startup Timing` reported + /// `had_unclean_shutdown = true` on ~every sample. + private var uncleanShutdownVerdict: Bool? + /// The user ID this database is configured for (nil = not yet configured → "anonymous") private var configuredUserId: String? @@ -332,6 +340,10 @@ actor RewindDatabase { initializationTask = nil runningFlagPath = nil openedForUserId = nil + // The database identity is being torn down, so the latched verdict no longer + // describes anything. The next performInitialization() makes a fresh + // authoritative observation for whichever user it opens. + uncleanShutdownVerdict = nil initGeneration += 1 poolEpoch += 1 log("RewindDatabase: Closed database (generation \(initGeneration), pool epoch \(poolEpoch))") @@ -383,9 +395,17 @@ actor RewindDatabase { } /// Check if the previous session ended with an unclean shutdown (crash, force quit, etc.) + /// + /// Order-independent: whoever observes first latches the verdict for the whole + /// process, and `performInitialization()` latches it before it writes this + /// session's own running flag. A later caller therefore reads the previous + /// session's state, not this one's. func hadUncleanShutdown() -> Bool { + if let uncleanShutdownVerdict { return uncleanShutdownVerdict } let flagPath = userBaseDirectory().appendingPathComponent(".omi_running").path - return FileManager.default.fileExists(atPath: flagPath) + let verdict = FileManager.default.fileExists(atPath: flagPath) + uncleanShutdownVerdict = verdict + return verdict } /// Initialize the database with migrations. @@ -471,6 +491,13 @@ actor RewindDatabase { // Detect unclean shutdown: if the running flag file exists, the previous launch // didn't exit cleanly (crash, force quit, power loss) let previousCrashed = FileManager.default.fileExists(atPath: flagPath) + // This is the authoritative, user-scoped observation and it happens before + // this session's flag is written below. Latch it here so a startup-timing + // reader that arrives after the database opened still reports the previous + // session, whatever order the storage actors initialized in. + if uncleanShutdownVerdict == nil { + uncleanShutdownVerdict = previousCrashed + } if previousCrashed { log("RewindDatabase: Unclean shutdown detected (running flag exists)") } diff --git a/desktop/macos/Desktop/Sources/ViewModelContainer.swift b/desktop/macos/Desktop/Sources/ViewModelContainer.swift index f2a5ad09ce6..a486d51216f 100644 --- a/desktop/macos/Desktop/Sources/ViewModelContainer.swift +++ b/desktop/macos/Desktop/Sources/ViewModelContainer.swift @@ -90,15 +90,18 @@ class ViewModelContainer: ObservableObject { // API calls and data fetches continue in the background isInitialLoadComplete = true loadedUserId = currentUserId - let timeToInteractive = CFAbsoluteTimeGetCurrent() - startupStart + // This is the critical startup path inside loadAllData, not time from + // process start. It is reported as `data_load_ms`; `time_to_interactive_ms` + // comes from the kernel's process-start stamp. + let dataLoadDuration = CFAbsoluteTimeGetCurrent() - startupStart // Track startup timing logPerf( - "DATA LOAD: DB init \(String(format: "%.1f", dbInitDuration * 1000))ms, time-to-interactive \(String(format: "%.1f", timeToInteractive * 1000))ms, uncleanShutdown=\(hadUncleanShutdown)" + "DATA LOAD: DB init \(String(format: "%.1f", dbInitDuration * 1000))ms, data load \(String(format: "%.1f", dataLoadDuration * 1000))ms, uncleanShutdown=\(hadUncleanShutdown)" ) AnalyticsManager.shared.trackStartupTiming( dbInitMs: dbInitDuration * 1000, - timeToInteractiveMs: timeToInteractive * 1000, + dataLoadMs: dataLoadDuration * 1000, hadUncleanShutdown: hadUncleanShutdown, databaseInitFailed: databaseInitFailed ) diff --git a/desktop/macos/Desktop/Tests/AppStartupTimingTests.swift b/desktop/macos/Desktop/Tests/AppStartupTimingTests.swift new file mode 100644 index 00000000000..5e47e23b2bd --- /dev/null +++ b/desktop/macos/Desktop/Tests/AppStartupTimingTests.swift @@ -0,0 +1,58 @@ +import XCTest + +@testable import Omi_Computer + +/// `App Startup Timing` reported `time_to_interactive_ms` of 11–131ms, which is +/// not a cold start of this app. It was the duration of +/// `ViewModelContainer.loadAllData()`, which begins long after `main()`. These +/// tests pin the replacement measurement. +final class AppStartupTimingTests: XCTestCase { + func testProcessStartIsReadFromTheKernelAndPrecedesNow() throws { + let start = try XCTUnwrap( + AppStartupTiming.processStartDate(), + "the kernel process table is the only source for a real process start") + XCTAssertLessThanOrEqual(start, Date(), "a process cannot start in the future") + + let elapsed = try XCTUnwrap(AppStartupTiming.millisecondsSinceProcessStart()) + XCTAssertGreaterThan( + elapsed, 0, + "time from process start to now must be positive; a zero here means the stamp was not read") + } + + /// The old measurement started inside `loadAllData()`. The new one starts at + /// exec, so it must include everything before the data load — otherwise the + /// rename bought nothing. + func testProcessStartPrecedesAnyTimestampTakenByOurOwnCode() throws { + let start = try XCTUnwrap(AppStartupTiming.processStartDate()) + let takenNow = Date() + XCTAssertLessThan( + start, takenNow, + "any Date() our code can take is necessarily after the kernel's exec stamp") + XCTAssertGreaterThan( + AppStartupTiming.elapsedMilliseconds(from: start, to: takenNow), + 0) + } + + func testElapsedMillisecondsConvertsAndNeverGoesNegative() { + let base = Date(timeIntervalSince1970: 1_000) + XCTAssertEqual( + AppStartupTiming.elapsedMilliseconds(from: base, to: base.addingTimeInterval(1.5)), + 1_500, + accuracy: 0.001) + + // Both instants come from the wall clock, so an adjustment between them can + // invert them. A startup metric must never report a negative duration. + XCTAssertEqual( + AppStartupTiming.elapsedMilliseconds(from: base, to: base.addingTimeInterval(-30)), + 0, + accuracy: 0.001) + } + + /// When the kernel lookup fails the property is omitted rather than replaced + /// with a plausible-looking number, which is how the implausible 11–131ms + /// values became indistinguishable from real ones. + func testMissingProcessStartYieldsNoMeasurementRatherThanAFabricatedOne() { + XCTAssertNil( + AppStartupTiming.millisecondsSinceProcessStart(now: Date(), processStart: nil)) + } +} diff --git a/desktop/macos/Desktop/Tests/RewindDatabaseLifecycleTests.swift b/desktop/macos/Desktop/Tests/RewindDatabaseLifecycleTests.swift index 4ccc9d3a5bb..ef1aad27b8b 100644 --- a/desktop/macos/Desktop/Tests/RewindDatabaseLifecycleTests.swift +++ b/desktop/macos/Desktop/Tests/RewindDatabaseLifecycleTests.swift @@ -132,6 +132,75 @@ final class RewindDatabaseLifecycleTests: XCTestCase { RewindDatabase.currentUserId = nil } + /// `App Startup Timing` reported `had_unclean_shutdown = true` on 10 of 11 + /// samples. The flag file is created at the end of `performInitialization()`, + /// so any of the seventeen storage actors that open the database lazily could + /// beat the startup-timing reader to it — after which the reader observed + /// *this* session's flag and called every launch a crash. The verdict must be + /// a property of the process, not of who asked first. + func testUncleanShutdownVerdictSurvivesTheDatabaseOpeningFirst() async throws { + let testUserId = "rewind-db-unclean-order-\(UUID().uuidString)" + let applicationSupportDirectory = try XCTUnwrap( + FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask).first + ) + let userDir = + applicationSupportDirectory + .appendingPathComponent("Omi", isDirectory: true) + .appendingPathComponent("users", isDirectory: true) + .appendingPathComponent(testUserId, isDirectory: true) + defer { try? FileManager.default.removeItem(at: userDir) } + + await RewindDatabase.shared.close() + RewindDatabase.currentUserId = testUserId + await RewindDatabase.shared.configure(userId: testUserId) + + // A storage actor opens the database before anything reads the verdict. + try await RewindDatabase.shared.initialize() + let runningFlag = userDir.appendingPathComponent(".omi_running") + XCTAssertTrue( + FileManager.default.fileExists(atPath: runningFlag.path), + "this session's running flag must exist, otherwise the test proves nothing") + + let verdict = await RewindDatabase.shared.hadUncleanShutdown() + XCTAssertFalse( + verdict, + "the previous session ended cleanly; this session's own running flag must not be read as a crash") + + await RewindDatabase.shared.close() + RewindDatabase.currentUserId = nil + } + + /// The latch must not swallow a real crash: a running flag left behind by a + /// previous session still reports unclean, whatever order it is read in. + func testPreviousSessionCrashIsStillReportedAfterTheDatabaseOpens() async throws { + let testUserId = "rewind-db-unclean-crash-\(UUID().uuidString)" + let applicationSupportDirectory = try XCTUnwrap( + FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask).first + ) + let userDir = + applicationSupportDirectory + .appendingPathComponent("Omi", isDirectory: true) + .appendingPathComponent("users", isDirectory: true) + .appendingPathComponent(testUserId, isDirectory: true) + defer { try? FileManager.default.removeItem(at: userDir) } + + // Simulate a previous launch that never removed its running flag. + try FileManager.default.createDirectory(at: userDir, withIntermediateDirectories: true) + FileManager.default.createFile( + atPath: userDir.appendingPathComponent(".omi_running").path, contents: nil) + + await RewindDatabase.shared.close() + RewindDatabase.currentUserId = testUserId + await RewindDatabase.shared.configure(userId: testUserId) + try await RewindDatabase.shared.initialize() + + let verdict = await RewindDatabase.shared.hadUncleanShutdown() + XCTAssertTrue(verdict, "a stale running flag from the previous session is a real unclean shutdown") + + await RewindDatabase.shared.close() + RewindDatabase.currentUserId = nil + } + func testPoolGenerationAdvancesAcrossReopen() async throws { let testUserId = "rewind-db-pool-generation-\(UUID().uuidString)" let applicationSupportDirectory = try XCTUnwrap( diff --git a/desktop/macos/changelog/unreleased/20260826-app-startup-timing.json b/desktop/macos/changelog/unreleased/20260826-app-startup-timing.json new file mode 100644 index 00000000000..3b92f1a9532 --- /dev/null +++ b/desktop/macos/changelog/unreleased/20260826-app-startup-timing.json @@ -0,0 +1,3 @@ +{ + "change": "Startup timing is measured and reported again, from real process start, and no longer calls every clean launch a crash" +} diff --git a/desktop/macos/e2e/flows/harness-smoke.yaml b/desktop/macos/e2e/flows/harness-smoke.yaml index 5c9030b2f0c..15220a5fd44 100644 --- a/desktop/macos/e2e/flows/harness-smoke.yaml +++ b/desktop/macos/e2e/flows/harness-smoke.yaml @@ -20,6 +20,7 @@ covers: - desktop/macos/Desktop/Sources/DesktopKeychainStore.swift - desktop/macos/Desktop/Sources/Logger.swift - desktop/macos/Desktop/Sources/Observability/SentryBeforeSendPolicy.swift + - desktop/macos/Desktop/Sources/Observability/AppStartupTiming.swift - desktop/macos/Desktop/Sources/ClientDeviceService.swift - desktop/macos/Desktop/Sources/LocalAgentAPIServer.swift - desktop/macos/Desktop/Sources/AgentSyncService.swift