feat: [SDK-5581] record a startup timeline for dispatchers and init

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/BootstrapDispatcherPools.kt

@@ -145,7 +145,7 @@ private class GateDispatcher(
 
             if (next == null) {
                 val closed = synchronized(lock) { state == LaneState.CLOSED }
-                if (closed) newTarget.close()
+                if (closed) newTarget.close() else StartupTimeline.laneReady(lane)
                 return
             }
             dispatchSafely(newTarget.dispatcher, next.first, next.second)

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/LazyDispatcherPools.kt

@@ -32,10 +32,13 @@ internal class LazyDispatcherPools : DispatcherPools {
     private val serialScopeLazy = lazy { CoroutineScope(SupervisorJob() + serialLane.dispatcher) }
     private val ingressScopeLazy = lazy { CoroutineScope(SupervisorJob() + ingressLane.dispatcher) }
 
-    override val ioScope: CoroutineScope get() = ioScopeLazy.value
-    override val defaultScope: CoroutineScope get() = defaultScopeLazy.value
-    override val serialIOScope: CoroutineScope get() = serialScopeLazy.value
-    override val ingressScope: CoroutineScope get() = ingressScopeLazy.value
+    override val ioScope: CoroutineScope get() = built(ioScopeLazy)
+    override val defaultScope: CoroutineScope get() = built(defaultScopeLazy)
+    override val serialIOScope: CoroutineScope get() = built(serialScopeLazy)
+    override val ingressScope: CoroutineScope get() = built(ingressScopeLazy)
+
+    // Timed only until built: main can build a lane itself, or wait on prewarm building it.
+    private fun <T> built(lazy: Lazy<T>): T = if (lazy.isInitialized()) lazy.value else StartupTimeline.mainBuildingLane { lazy.value }
 
     private val prewarmThread = AtomicReference<Thread?>(null)
 
@@ -137,19 +140,24 @@ internal class LazyDispatcherPools : DispatcherPools {
             return created.takeUnless { it.isShutdown }
         }
 
-        override val dispatcher: CoroutineDispatcher by lazy {
-            val executor = executorLazy.value
-            if (executor == null) {
-                lane.fallbackDispatcher()
-            } else {
-                try {
-                    executor.asCoroutineDispatcher()
-                } catch (t: Throwable) {
-                    OneSignalDispatchers.logFailure("lazy $lane fell back", t)
-                    lane.fallbackDispatcher()
-                }
+        private val dispatcherLazy =
+            lazy {
+                val executor = executorLazy.value
+                val built =
+                    if (executor == null) {
+                        lane.fallbackDispatcher()
+                    } else {
+                        try {
+                            executor.asCoroutineDispatcher()
+                        } catch (t: Throwable) {
+                            OneSignalDispatchers.logFailure("lazy $lane fell back", t)
+                            lane.fallbackDispatcher()
+                        }
+                    }
+                built.also { StartupTimeline.laneReady(lane) }
             }
-        }
+
+        override val dispatcher: CoroutineDispatcher get() = built(dispatcherLazy)
 
         override fun executor(): ThreadPoolExecutor? =
             if (executorLazy.isInitialized()) executorLazy.value else null

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt

@@ -55,7 +55,13 @@ object OneSignalDispatchers {
                 poolsRef?.let { return it }
                 choosePools(bootstrapEnabledForTest, AppContext::get).also { choice ->
                     published = poolsRef
-                    if (published == null) poolsRef = choice.pools else choice.pools.shutdown()
+                    if (published != null) {
+                        choice.pools.shutdown()
+                    } else {
+                        // Before publishing: below API 24 this mark is the origin every other mark is measured from.
+                        StartupTimeline.poolsChosen(choice.mode, choice.detail)
+                        poolsRef = choice.pools
+                    }
                 }
             }
         if (!Thread.holdsLock(poolsLock)) recordChoice(choice)

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/PoolChoice.kt

@@ -11,7 +11,8 @@ internal class PoolChoice(
     val warn: Boolean,
     val failure: Throwable? = null,
 ) {
-    val summary: String get() = "$detail; pools=${if (pools is LazyDispatcherPools) "lazy" else "bootstrap"}"
+    val mode: String get() = if (pools is LazyDispatcherPools) "lazy" else "bootstrap"
+    val summary: String get() = "$detail; pools=$mode"
 }
 
 // Every launch in the process goes through this, so a failed choice must not throw.

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt

@@ -0,0 +1,223 @@
+package com.onesignal.common.threading
+
+import android.os.Build
+import android.os.Looper
+import android.os.Process
+import android.os.SystemClock
+import java.util.concurrent.atomic.AtomicBoolean
+import java.util.concurrent.atomic.AtomicInteger
+import java.util.concurrent.atomic.AtomicLong
+
+/**
+ * When this process's dispatchers and init reached each startup step, on the uptime clock.
+ * One per process: marks are first-write-wins, except init marks, which a retry after a failed init resets.
+ */
+@Suppress("TooManyFunctions")
+internal object StartupTimeline {
+    private const val UNSET = -1L
+    private const val NANOS_PER_MS = 1_000_000L
+
+    // An ANR this long after init ended is not about startup.
+    private const val ANR_RELEVANCE_MS = 30_000L
+
+    private val processStart = AtomicLong(UNSET)
+    private val poolsChosen = AtomicLong(UNSET)
+
+    @Volatile private var pools = "unknown"
+
+    @Volatile private var choice = "unknown"
+    private val ioReady = AtomicLong(UNSET)
+    private val lanesReady = AtomicLong(UNSET)
+    private val readyLaneBits = AtomicInteger(0)
+    private val initAttempts = AtomicInteger(0)
+    private val initQueued = AtomicLong(UNSET)
+    private val initStarted = AtomicLong(UNSET)
+    private val initEnded = AtomicLong(UNSET)
+
+    @Volatile private var initResult = "pending"
+    private val reported = AtomicBoolean(false)
+
+    private val mainWait = MainTimer()
+    private val mainLaneBuild = MainTimer()
+
+    // Touched only on main: a scope build reads the dispatcher, and that must not count twice.
+    private var mainTimingLane = false
+
+    init {
+        resetForTest()
+    }
+
+    fun poolsChosen(
+        mode: String,
+        detail: String,
+    ) {
+        if (!poolsChosen.compareAndSet(UNSET, now())) return
+        pools = mode
+        choice = detail
+    }
+
+    /** Bootstrap marks a lane once its threads are started; lazy marks it once built, as threads start on first task. */
+    fun laneReady(lane: Lane) {
+        val at = now()
+        if (lane == Lane.IO) ioReady.compareAndSet(UNSET, at)
+        val all = (1 shl Lane.values().size) - 1
+        while (true) {
+            val bits = readyLaneBits.get()
+            val next = bits or (1 shl lane.ordinal)
+            if (bits == next || readyLaneBits.compareAndSet(bits, next)) {
+                if (next == all) lanesReady.compareAndSet(UNSET, at)
+                return
+            }
+        }
+    }
+
+    /** Call when init moves to in progress. A retry after a failed init times and reports the new attempt. */
+    fun initAttempt() {
+        if (initAttempts.incrementAndGet() == 1) return
+        listOf(initQueued, initStarted, initEnded).forEach { it.set(UNSET) }
+        initResult = "pending"
+        reported.set(false)
+    }
+
+    fun initQueued() {
+        initQueued.compareAndSet(UNSET, now())
+    }
+
+    fun initStarted() {
+        initStarted.compareAndSet(UNSET, now())
+    }
+
+    fun initEnded(result: String) {
+        if (initEnded.compareAndSet(UNSET, now())) initResult = result
+    }
+
+    /** Runs [block], counting its duration as main blocked on init when called on main. */
+    fun <T> mainWaitingForInit(block: () -> T): T {
+        if (!isMainThread()) return block()
+        return mainWait.time(block)
+    }
+
+    /** Runs [block], counting its duration as main building (or waiting on) a lane when called on main. */
+    fun <T> mainBuildingLane(block: () -> T): T {
+        if (!isMainThread() || mainTimingLane) return block()
+        mainTimingLane = true
+        try {
+            return mainLaneBuild.time(block)
+        } finally {
+            mainTimingLane = false
+        }
+    }
+
+    /** True once per init attempt that reaches the end, for whoever logs the timeline. */
+    fun claimReport(): Boolean = reported.compareAndSet(false, true)
+
+    /**
+     * Steps (`*_ms` except the two below) are milliseconds since [originName], "-" when not reached.
+     * `main_wait_ms` and `main_lane_build_ms` are durations.
+     */
+    fun summary(): String {
+        val origin = origin()
+        fun at(value: Long) = if (value == UNSET || origin == UNSET) "-" else (value - origin).toString()
+        val wait = mainWait.read()
+        val build = mainLaneBuild.read()
+        return "startup_timeline pools=$pools choice=\"$choice\" pools_chosen_ms=${at(poolsChosen.get())} " +
+            "io_ready_ms=${at(ioReady.get())} lanes_ready_ms=${at(lanesReady.get())} " +
+            "init_attempts=${initAttempts.get()} init_queued_ms=${at(initQueued.get())} " +
+            "init_started_ms=${at(initStarted.get())} init_ended_ms=${at(initEnded.get())} init_result=$initResult " +
+            "main_wait_ms=${wait.ms} main_waits=${wait.count}${wait.ongoing("main_wait")} " +
+            "main_lane_build_ms=${build.ms}${build.ongoing("main_lane_build")} origin=${originName()}"
+    }
+
+    /** [summary] for an ANR record, or null when the ANR is long past startup. */
+    fun anrSummary(): String? {
+        val ended = initEnded.get()
+        if (ended != UNSET && now() - ended >= ANR_RELEVANCE_MS) return null
+        return summary()
+    }
+
+    internal fun resetForTest() {
+        processStart.set(processStartUptime())
+        listOf(poolsChosen, ioReady, lanesReady, initQueued, initStarted, initEnded).forEach { it.set(UNSET) }
+        mainWait.reset()
+        mainLaneBuild.reset()
+        readyLaneBits.set(0)
+        initAttempts.set(0)
+        pools = "unknown"
+        choice = "unknown"
+        initResult = "pending"
+        reported.set(false)
+    }
+
+    private fun origin(): Long = processStart.get().takeIf { it != UNSET } ?: poolsChosen.get()
+
+    // Below API 24 there is no process start time, so steps are relative to the pool choice.
+    private fun originName(): String = if (processStart.get() != UNSET) "process" else "pools"
+
+    // Runs in the object's initializer, where a throw would make the class unloadable.
+    @Suppress("SwallowedException")
+    private fun processStartUptime(): Long =
+        try {
+            if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) Process.getStartUptimeMillis() else UNSET
+        } catch (_: RuntimeException) {
+            UNSET
+        }
+
+    // Marks run inside lane builds and init, so a missing Android runtime (plain JVM tests) must not throw.
+    @Suppress("SwallowedException")
+    private fun now(): Long =
+        try {
+            SystemClock.uptimeMillis()
+        } catch (_: RuntimeException) {
+            System.nanoTime() / NANOS_PER_MS
+        }
+
+    @Suppress("SwallowedException")
+    private fun isMainThread(): Boolean =
+        try {
+            Looper.myLooper() == Looper.getMainLooper()
+        } catch (_: RuntimeException) {
+            false
+        }
+
+    private class Timing(
+        val ms: Long,
+        val count: Int,
+        private val running: Boolean,
+    ) {
+        fun ongoing(name: String) = if (running) " ${name}_ongoing=true" else ""
+    }
+
+    // Total and in-progress time change together, so a reading never drops or double counts a span.
+    private class MainTimer {
+        private var total = 0L
+        private var count = 0
+        private var since = UNSET
+
+        fun <T> time(block: () -> T): T {
+            val start = now()
+            synchronized(this) {
+                since = start
+                count++
+            }
+            try {
+                return block()
+            } finally {
+                val end = now()
+                synchronized(this) {
+                    since = UNSET
+                    total += end - start
+                }
+            }
+        }
+
+        @Synchronized
+        fun read() = Timing(total + if (since != UNSET) now() - since else 0, count, since != UNSET)
+
+        @Synchronized
+        fun reset() {
+            total = 0
+            count = 0
+            since = UNSET
+        }
+    }
+}

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt

@@ -221,8 +221,9 @@ internal fun buildAnrCrashData(
     threadName: String,
     stackTrace: Array<StackTraceElement>,
     unresponsiveDurationMs: Long,
+    startupTimeline: String? = null,
 ): CrashData {
-    val message = "Application Not Responding: Main thread blocked for ${unresponsiveDurationMs}ms"
+    val message = "Application Not Responding: Main thread blocked for ${unresponsiveDurationMs}ms" + timelineSuffix(startupTimeline)
     return CrashData(
         threadName = threadName,
         exceptionType = ANR_EXCEPTION_TYPE,
@@ -231,6 +232,9 @@ internal fun buildAnrCrashData(
     )
 }
 
+// Appended last so dashboards grouping on the message prefix keep grouping.
+private fun timelineSuffix(startupTimeline: String?): String = startupTimeline?.let { " | $it" }.orEmpty()
+
 /**
  * Builds the non-fatal record for a backgrounded main-thread block, with a
  * [buildBlockFingerprint] summary embedded in the message.
@@ -239,9 +243,11 @@ internal fun buildBackgroundBlockCrashData(
     threadName: String,
     stackTrace: Array<StackTraceElement>,
     unresponsiveDurationMs: Long,
+    startupTimeline: String? = null,
 ): CrashData {
     val message =
-        "Background main-thread block for ${unresponsiveDurationMs}ms | ${buildBlockFingerprint(stackTrace)}"
+        "Background main-thread block for ${unresponsiveDurationMs}ms | ${buildBlockFingerprint(stackTrace)}" +
+            timelineSuffix(startupTimeline)
     return CrashData(
         threadName = threadName,
         exceptionType = BACKGROUND_BLOCK_EXCEPTION_TYPE,

OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/logging/logger/android/AndroidLogAnrDetector.kt

@@ -3,6 +3,7 @@ package com.onesignal.debug.internal.logging.logger.android
 import android.os.Handler
 import android.os.Looper
 import android.os.SystemClock
+import com.onesignal.common.threading.StartupTimeline
 import com.onesignal.debug.internal.crash.AnrCheckEvaluator
 import com.onesignal.debug.internal.crash.AnrCheckResult
 import com.onesignal.debug.internal.crash.AnrConstants
@@ -151,7 +152,7 @@ internal class AndroidLogAnrDetector(
                 logger.debug("$TAG: ANR not OneSignal-related, skipping report")
                 return
             }
-            crashReporter.saveCrash(buildAnrCrashData(mainThread.name, stackTrace, unresponsiveDurationMs))
+            crashReporter.saveCrash(buildAnrCrashData(mainThread.name, stackTrace, unresponsiveDurationMs, StartupTimeline.anrSummary()))
             logger.info("$TAG: ANR report saved")
         } catch (t: Throwable) {
             logger.error("$TAG: failed to report ANR: ${t.message}")
@@ -168,7 +169,9 @@ internal class AndroidLogAnrDetector(
                 logger.debug("$TAG: background block not OneSignal-related, skipping")
                 return
             }
-            crashReporter.saveNonFatal(buildBackgroundBlockCrashData(mainThread.name, stackTrace, unresponsiveDurationMs))
+            crashReporter.saveNonFatal(
+                buildBackgroundBlockCrashData(mainThread.name, stackTrace, unresponsiveDurationMs, StartupTimeline.anrSummary()),
+            )
             logger.info("$TAG: background block warning recorded")
         } catch (t: Throwable) {
             logger.error("$TAG: failed to record background block: ${t.message}")