[abdulraqeeb33]

Description

One Line Summary

Record a per-process startup timeline (pool choice, lane readiness, init phases, main thread blocking) and log it once at INFO when init ends, plus attach it to ANR records near startup.

Details

Motivation

We still see ANRs around SDK startup and can't tell which of these caused them:

• init waited for a thread (queued to started)
• init's own work was slow (started to ended)
• the host app blocked main on us, by calling a blocking API before init finished (waitForInit)
• main built a lazy lane itself

This PR records those steps so we can measure them instead of guessing.

No new flag. The summary is a single Logging.info line, so it only leaves the device when remote logging is raised to INFO. The plan:

1. Raise remote logging to INFO for about an hour on a set of apps, covering both pool modes (sdk_dispatcher_bootstrap on and off).
2. Collect the startup_timeline lines, then set remote logging back to its default.
3. Compare the modes: time from init queued to init started, how long main was blocked in waitForInit, and how long main spent building lanes.

We expect this to show that most main-thread freezes come from the host app calling blocking SDK methods during startup, not from our internal lanes. That gives us data to push customers toward the suspend APIs (initWithContextSuspend, loginSuspend and friends), while we keep the internal lanes efficient.

What gets recorded

StartupTimeline is a first-write-wins set of marks on the uptime clock (one per process). Only the main-wait counters share a small lock, so a summary never splits a wait. Times are relative to process start (API 24+) or, before that, to the pool choice:

• pools, choice, pools_chosen_ms: which pools were chosen and why
• io_ready_ms, lanes_ready_ms: when IO and then all four lanes were ready. Bootstrap marks a lane once its threads are started; lazy marks it once the dispatcher is built (threads start on the first task). Compare these across modes with that in mind.
• init_attempts: how many times init moved to in progress. A retry after a failed init resets the init marks and is logged again.
• init_queued_ms, init_started_ms, init_ended_ms, init_result
• main_wait_ms, main_waits, main_wait_ongoing: time main spent blocked in waitForInit on an in-progress init, including a wait still going when the line is written. Calls before init started or after it failed throw immediately and aren't counted.
• main_lane_build_ms, main_lane_build_ongoing: time main spent building, or waiting on, a lazy lane, including a build still in progress. The IO lane is resolved before init_queued, so that build isn't counted as init's queue wait.

Example:

startup_timeline pools=lazy choice="off, flag not in cache" pools_chosen_ms=412 io_ready_ms=431 lanes_ready_ms=-
init_attempts=1 init_queued_ms=415 init_started_ms=433 init_ended_ms=980 init_result=success main_wait_ms=540 main_waits=1
main_lane_build_ms=19 origin=process

Scope

• Logged once per init attempt, when it completes. A throwing customer log listener can't fail init.
• ANR and background-block records less than 30s after init ended get the same summary appended to their message. It's appended last, so dashboards that group on the message prefix keep grouping.
• Recording never throws into lane construction or init, including in plain JVM tests where Looper and SystemClock are stubs.
• No public API change. No change to which pools are chosen, or to how lanes or init behave.

Testing

Unit testing

StartupTimelineTests (Robolectric, 15 tests):

• first mark wins, lanes-ready dedupe, main waits counted including an ongoing one, a background thread isn't counted, a nested lane build is counted once, a lane build still in progress is counted
• lazy pools count main building a lane; bootstrap pools never have main build one
• OneSignalImp logs the timeline once and counts main blocked in waitForInit; a throwing log listener doesn't fail init; waitForInit before init started isn't counted
• a retry after a failed init is timed and reported as its own attempt
• ANR records carry the timeline, and records 30s or more after init ended don't (checked at 29,999 and 30,000 ms)

Each assertion was red-checked by removing the code it defends.

Manual testing

Not yet on a device. The INFO window described above is the real-world check.

Affected code checklist

• Notifications
  • Display
  • Open
  • Push Processing
  • Confirm Deliveries
• Outcomes
• Sessions
• In-App Messaging
• REST API requests
• Public API changes

Checklist

Overview

• I have filled out all REQUIRED sections above
• PR does one thing
• Any Public API changes are explained in the PR details and conform to existing APIs

Testing

• I have included test coverage for these changes, or explained why they are not needed
• All automated tests pass, or I explained why that is not possible
• I have personally tested this on my device, or explained why that is not possible

Final pass

• Code is as readable as possible.
• I have reviewed this PR myself, ensuring it meets each checklist item

[github-actions]

📊 Diff Coverage Report

Diff Coverage Report (Changed Lines Only)

Gate: aggregate coverage on changed executable lines must be ≥ 80% (JaCoCo line data for lines touched in the diff).

Changed Files Coverage

• BootstrapDispatcherPools.kt: 1/1 touched executable lines (100.0%) (1 touched lines in diff)
• LazyDispatcherPools.kt: 15/17 touched executable lines (88.2%) (24 touched lines in diff)
• OneSignalDispatchers.kt: 4/4 touched executable lines (100.0%) (7 touched lines in diff)
• PoolChoice.kt: 2/2 touched executable lines (100.0%) (2 touched lines in diff)
• StartupTimeline.kt: 113/114 touched executable lines (99.1%) (223 touched lines in diff)
• AnrCheckEvaluator.kt: 6/6 touched executable lines (100.0%) (8 touched lines in diff)
• AndroidLogAnrDetector.kt: 0/3 touched executable lines (0.0%) (5 touched lines in diff)
  • 3 uncovered touched lines in this file
• OneSignalImp.kt: 17/17 touched executable lines (100.0%) (27 touched lines in diff)

Overall (aggregate gate)

158/164 touched executable lines covered (96.3% — requires ≥ 80%)

Per-file detail (informational; gate is aggregate above):

• AndroidLogAnrDetector.kt: 0.0% (3 uncovered touched lines)

📥 View workflow run

[cursor]

Multi-model review

Models: Claude Opus 5.5, GPT 5.6 Sol, Grok 4.7. Scope: +411/−24 Kotlin (StartupTimeline + call sites). No generated/lock/vendor files.

Act on

Logging.info in completeInit can flip SUCCESS to FAILED. (3/3) The new log runs after suspendCompletion.complete() but still inside internalInit's try. Logging.log invokes host ILogListeners with no catch. A throw is caught by internalInit, which calls completeInit(FAILED) after waiters already saw SUCCESS. reportChoice already wraps Logging.warn for this reason.

main_wait_ms is not a consistent snapshot. (3/3) Writer clears mainWaitSince then adds to mainWaitTotal. A concurrent summary() — the completeInit log, or an ANR — can double-count or report 0. That INFO line is the record most likely to be wrong.

Consider

Retry-after-FAILED is invisible. (Opus+Grok) Marks and claimReport are process-lifetime first-write-wins. A first FAILED (direct boot, missing appId) consumes the log and starts the 30s ANR window; a later success never logs, and ANRs after 30s get no timeline.

main_lane_build_ms has no in-progress mark. (Sol) Unlike mainWaitSince, an ANR while main is inside mainBuildingLane reports main_lane_build_ms=0.

poolsRef is published before poolsChosen. (Sol) Below API 24 the origin is the pool-choice mark. Another thread can queue init or build a lane first, producing negative offsets.

Noted

• 30s ANR window is measured at report time, not block start (Opus+Grok)
• main_wait_ongoing=true test can flake vs main's finally (Opus+Grok)
• timestamp CAS can race string writes (pools=unknown / init_result=pending) (Opus)
• Process.getStartUptimeMillis() in class init is unguarded, unlike now() (Opus+Grok)
• re-entrant waitForInit from a log listener overwrites mainWaitSince (Grok; the deadlock itself is pre-existing)

Dismissed

Fallback lanes counting as ready: the mark is dispatcher-ready, including fallback, which matches the field name.

  

_{Sent by Cursor Automation: PR Reviews}

[abdulraqeeb33]

Thanks. Addressed in 40ff381 and 4f70c77.

1. Throwing log listener can no longer fail init.
2. main_wait_ms is a consistent snapshot.
3. Retry after FAILED resets the init marks and logs again (init_attempts).
4. main_lane_build_ms counts a build still in progress (main_lane_build_ongoing).
5. poolsChosen is marked inside poolsLock before poolsRef is published.
6. Process.getStartUptimeMillis() is guarded.
7. The racy main_wait_ongoing test now waits on the summary instead of sleeping.

Leaving the rest of the noted items as is: the string vs CAS window, the 30s window measured at report time, and re-entrant waitForInit from a listener, which deadlocks before this PR anyway.

[fadi-george]

Minor issues:

• OneSignalImp.kt:592, reportStartupTimeline only catches RuntimeException but internalInit catches Exception, so a Kotlin log listener throwing a checked exception can still flip a finished init to FAILED. Catch Throwable like logStartupDiagnostics does.

[abdulraqeeb33]

Good catch, fixed in #2812 (catches Throwable, test now throws IOException).