Skip to content

fix(desktop): make App Startup Timing measure a startup again - #12271

Open
Git-on-my-level wants to merge 1 commit into
mainfrom
telemetry/app-startup-timing
Open

fix(desktop): make App Startup Timing measure a startup again#12271
Git-on-my-level wants to merge 1 commit into
mainfrom
telemetry/app-startup-timing

Conversation

@Git-on-my-level

@Git-on-my-level Git-on-my-level commented Aug 26, 2026

Copy link
Copy Markdown
Collaborator

Defect

The 2026-08 macOS churn cohort analysis (omi-knowledge-base/projects/macos-churn-analysis/evidence/2026-08-26-macos-churn-cohort-analysis.md) records under "Methodology guardrails":

Instrumentation known-broken: App Startup Timing (11 samples/7 users cohort-wide; had_unclean_shutdown ~always true; implausible TTI values)

and under "Engineering leads": "no usable macOS startup-performance signal exists."

That is three separate defects, and the first one changes how the other two should be read.

1. The event does not reach PostHog at all

AnalyticsManager.trackStartupTiming writes only a Sentry breadcrumb:

// 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.

PostHog, $os = macOS, 2026-08-18 → 2026-08-25:

build App Startup Timing samples App Launched
0.12.187 0 4,380
0.12.213 0 1,188
0.12.144 0 667
0.11.420 7 64
0.11.360 6 26

Every 0.12.x build emits zero. The cohort's 11 samples are not a sampling defect — they are the last stragglers of an event that was retired from product analytics. So "the event rarely fires" is not the finding; "the event was deliberately moved to Sentry and nobody noticed the fleet metric died" is.

2. had_unclean_shutdown was a race, not a crash rate

.omi_running is created at the end of RewindDatabase.performInitialization(). Seventeen storage actors call RewindDatabase.shared.initialize() lazily, and any of them can beat ViewModelContainer.loadAllData() to it — the code even documents this ("TierManager triggers init early"). Once the database is open, hadUncleanShutdown() reads this session's flag and reports every clean launch as a crash.

3. TTI measured the wrong interval

timeToInteractive started at CFAbsoluteTimeGetCurrent() on the first line of loadAllData(), which runs long after main(). 11–131ms is a correct measurement of the wrong thing.

Fix

  • AnalyticsManager.trackStartupTiming emits App Startup Timing to PostHog again, once per process (loadAllData re-runs on an owner switch, and that is not a launch). The Sentry breadcrumb stays, so the numbers remain attached to a same-session crash report — Sentry answers "what did this crash look like", PostHog answers "is startup getting slower across the fleet", and only the second one was lost.
  • RewindDatabase latches the unclean-shutdown verdict at the first observation in the process, and performInitialization() latches it from previousCrashed before writing this session's flag. The verdict becomes a property of the process rather than of call order. close() clears the latch so a user retarget re-observes for the user it opens.
  • AppStartupTiming.processStartDate() reads kinfo_proc.kp_proc.p_starttime — the kernel's exec stamp, before dyld and before main. time_to_interactive_ms is measured from there, and is omitted rather than faked when the lookup fails.
  • The old measurement is kept under the name it deserves: data_load_ms.

Event shape change

db_init_ms             unchanged
data_load_ms           new  — what time_to_interactive_ms used to measure
time_to_interactive_ms same name, now measured from kernel process start
had_unclean_shutdown   unchanged name, now actually about the previous session
database_init_failed   unchanged

time_to_interactive_ms keeps its name and changes meaning. Historical values are not comparable — but there are 11 of them and they were wrong. Anything reading this property (the omi-posthog-macos skill documents it) should treat 0.12.x-and-later as a new series.

This adds a per-launch PostHog event, which moves the legacy all-events DAU insight (already labelled [Legacy] DAU — all events (instrumentation-sensitive)). Core Product DAU v1 — clean by platform is an explicit allowlist and is unaffected.

Proof

xcrun swift test --filter "AppStartupTimingTests|RewindDatabaseLifecycleTests" — 14 tests pass locally.

  • testUncleanShutdownVerdictSurvivesTheDatabaseOpeningFirst — opens the database first, asserts this session's flag exists (so the test cannot pass vacuously), then asserts the verdict is false. Mutation-checked: deleting the latch read makes this test fail with the exact production symptom.
  • testPreviousSessionCrashIsStillReportedAfterTheDatabaseOpens — a stale flag from a previous session still reports unclean, so the latch cannot swallow a real crash.
  • AppStartupTimingTests — the kernel stamp is read and precedes any Date() our own code can take; conversion floors at zero across a wall-clock adjustment; a failed lookup yields no measurement rather than a fabricated one.

Local make preflight passes. Full Swift contract CI (~42 min) runs after push; not claimed green here.

Invariants

  • INV-AUTH-1 — touched by path only (RewindDatabase.swift is in the desktop session-truth glob). This PR adds a latched boolean about the previous process's shutdown; it does not touch session death, invalidateSession, signOut(), Firebase credentials, or owner identity. close()/configure() semantics are unchanged apart from clearing that boolean.

Failure-Class: FC-alert-never-provably-fired

Line-Count-Exception: desktop/macos/Desktop/Sources/Rewind/Core/RewindDatabase.swift | 3481 -> 3508 | +27 lines: one optional Bool field, a latch read in hadUncleanShutdown(), a latch write in performInitialization(), a clear in close(), and the comments that explain the race. Splitting a 3.5k-line database class is the right cleanup but is not this telemetry fix's job, and folding it in would bury a 4-line behavior change in a move diff.


First commit is unrelated housekeeping needed to get any desktop PR past the local pre-push gate on Xcode 26.x (also in #12267 and #12269): a swift-format drift already on main and one implicit self capture that Swift 6.2 rejects and Xcode 16.4 accepts. It drops out on rebase once any of the three lands.

Review in cubic

Three separate defects, all of which the 2026-08 macOS churn cohort
analysis saw as one ("11 samples across 7 users; had_unclean_shutdown
true in 10/11; TTI of 11-131ms is implausible for a cold start").

1. It does not reach PostHog at all. `trackStartupTiming` writes only a
   Sentry breadcrumb, so the event stopped existing when that landed.
   PostHog, 2026-08-18 -> 2026-08-25, macOS: every 0.12.x build emits 0
   samples against 4,380 `App Launched` on 0.12.187 alone; the only
   samples in the whole window come from 0.11.x stragglers. The cohort's
   11 samples are not a sampling defect, they are the last of a retired
   event.

2. `had_unclean_shutdown` was true on nearly every sample because the
   read raced the write. `.omi_running` is created at the end of
   `performInitialization()`, and seventeen storage actors open the
   database lazily, so whichever one wins arrives before
   `ViewModelContainer.loadAllData()` reads the flag - which then sees
   *this* session's flag and calls the launch a crash.

3. `time_to_interactive_ms` measured `loadAllData()`, which starts long
   after `main()`. That is what produced 11-131ms.

## What changed

- `AnalyticsManager.trackStartupTiming` emits `App Startup Timing` to
  PostHog again, once per process (`loadAllData` re-runs on owner
  switch, and that is not a launch). The Sentry breadcrumb stays so the
  numbers remain attached to a same-session crash report.
- `RewindDatabase` latches the unclean-shutdown verdict at the first
  observation in the process, and `performInitialization()` latches it
  from `previousCrashed` before writing this session's flag. The verdict
  is now a property of the process, not of call order. `close()` clears
  the latch so a retarget re-observes for the user it opens.
- `AppStartupTiming.processStartDate()` reads
  `kinfo_proc.kp_proc.p_starttime` - the kernel's exec stamp, before
  dyld and before `main`. `time_to_interactive_ms` is measured from
  there, and is omitted rather than faked when the lookup fails.
- The old measurement is still reported, under the name it deserves:
  `data_load_ms`.

**`time_to_interactive_ms` keeps its name and changes meaning.** It now
includes process start. Existing values are not comparable, but there
are only 11 of them and they were wrong.

## Proof

- `RewindDatabaseLifecycleTests.testUncleanShutdownVerdictSurvivesTheDatabaseOpeningFirst`
  opens the database first, asserts this session's flag exists, then
  asserts the verdict is false. Removing the latch makes it fail
  (verified).
- `RewindDatabaseLifecycleTests.testPreviousSessionCrashIsStillReportedAfterTheDatabaseOpens`
  proves the latch does not swallow a real crash.
- `AppStartupTimingTests` pins that the kernel stamp is read and precedes
  any `Date()` our own code can take, that conversion floors at zero
  across a wall-clock adjustment, and that a failed lookup yields no
  measurement rather than a fabricated one.

14 tests pass locally.

Failure-Class: FC-alert-never-provably-fired
@Git-on-my-level
Git-on-my-level force-pushed the telemetry/app-startup-timing branch from ec8f908 to 284fc20 Compare August 27, 2026 03:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant