From 4c203658c4e4432541b9e947b9c4af993d09100e Mon Sep 17 00:00:00 2001 From: AR Abdul Azeez Date: Thu, 22 Oct 2026 13:16:26 -0500 Subject: [PATCH 1/3] feat: [SDK-5581] record a startup timeline for dispatchers and init Co-authored-by: Cursor --- .../threading/BootstrapDispatcherPools.kt | 2 +- .../common/threading/LazyDispatcherPools.kt | 40 ++-- .../common/threading/OneSignalDispatchers.kt | 1 + .../onesignal/common/threading/PoolChoice.kt | 3 +- .../common/threading/StartupTimeline.kt | 173 ++++++++++++++++ .../debug/internal/crash/AnrCheckEvaluator.kt | 10 +- .../logger/android/AndroidLogAnrDetector.kt | 7 +- .../com/onesignal/internal/OneSignalImp.kt | 14 +- .../common/threading/StartupTimelineTests.kt | 185 ++++++++++++++++++ 9 files changed, 411 insertions(+), 24 deletions(-) create mode 100644 OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt create mode 100644 OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/BootstrapDispatcherPools.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/BootstrapDispatcherPools.kt index 0d3d38b56..fac05c08d 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/BootstrapDispatcherPools.kt +++ b/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) diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/LazyDispatcherPools.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/LazyDispatcherPools.kt index 39e6d52e1..d03524e7e 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/LazyDispatcherPools.kt +++ b/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 built(lazy: Lazy): T = if (lazy.isInitialized()) lazy.value else StartupTimeline.mainBuildingLane { lazy.value } private val prewarmThread = AtomicReference(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 diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt index 4e2a5513f..ae7b8e74d 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt @@ -58,6 +58,7 @@ object OneSignalDispatchers { if (published == null) poolsRef = choice.pools else choice.pools.shutdown() } } + if (published == null) StartupTimeline.poolsChosen(choice.mode, choice.detail) if (!Thread.holdsLock(poolsLock)) recordChoice(choice) return published ?: choice.pools } diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/PoolChoice.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/PoolChoice.kt index 519582eae..07ea2a9d2 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/PoolChoice.kt +++ b/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. diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt new file mode 100644 index 000000000..87d2adfd7 --- /dev/null +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt @@ -0,0 +1,173 @@ +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. Splits a + * slow start into waiting for a thread (init queued to started) versus init's own work (started to + * ended), and records how much of that main spent blocked. Marks are first-write-wins and lock-free. + */ +@Suppress("TooManyFunctions") +internal object StartupTimeline { + private const val UNSET = -1L + + // 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 initQueued = AtomicLong(UNSET) + private val initStarted = AtomicLong(UNSET) + private val initEnded = AtomicLong(UNSET) + + @Volatile private var initResult = "pending" + private val mainWaitTotal = AtomicLong(0) + private val mainWaits = AtomicInteger(0) + private val mainWaitSince = AtomicLong(UNSET) + private val mainLaneBuild = AtomicLong(0) + private val reported = AtomicBoolean(false) + + // 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 + } + + 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 + } + } + } + + 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 mainWaitingForInit(block: () -> T): T { + if (!isMainThread()) return block() + val start = now() + mainWaitSince.set(start) + mainWaits.incrementAndGet() + try { + return block() + } finally { + mainWaitSince.set(UNSET) + mainWaitTotal.addAndGet(now() - start) + } + } + + /** Runs [block], counting its duration as main building (or waiting on) a lane when called on main. */ + fun mainBuildingLane(block: () -> T): T { + if (mainTimingLane || !isMainThread()) return block() + mainTimingLane = true + val start = now() + try { + return block() + } finally { + mainLaneBuild.addAndGet(now() - start) + mainTimingLane = false + } + } + + /** True once per process, for whoever logs the timeline. */ + fun claimReport(): Boolean = reported.compareAndSet(false, true) + + /** Every step as milliseconds since process start; "-" for a step not reached. */ + fun summary(): String { + val origin = origin() + fun at(value: Long) = if (value == UNSET || origin == UNSET) "-" else (value - origin).toString() + val ongoing = if (mainWaitSince.get() != UNSET) " main_wait_ongoing=true" else "" + 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_queued_ms=${at(initQueued.get())} init_started_ms=${at(initStarted.get())} " + + "init_ended_ms=${at(initEnded.get())} init_result=$initResult main_wait_ms=${mainWaitMs()} " + + "main_waits=${mainWaits.get()}$ongoing main_lane_build_ms=${mainLaneBuild.get()} 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(if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) Process.getStartUptimeMillis() else UNSET) + listOf(poolsChosen, ioReady, lanesReady, initQueued, initStarted, initEnded, mainWaitSince).forEach { it.set(UNSET) } + mainWaitTotal.set(0) + mainLaneBuild.set(0) + readyLaneBits.set(0) + mainWaits.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" + + private fun mainWaitMs(): Long { + val since = mainWaitSince.get() + return mainWaitTotal.get() + if (since != UNSET) now() - since else 0 + } + + // 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) { + UNSET + } + + @Suppress("SwallowedException") + private fun isMainThread(): Boolean = + try { + Looper.myLooper() == Looper.getMainLooper() + } catch (_: RuntimeException) { + false + } +} diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt index 4f9d580bd..720f5358f 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt @@ -221,8 +221,9 @@ internal fun buildAnrCrashData( threadName: String, stackTrace: Array, 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, @@ -235,13 +236,18 @@ internal fun buildAnrCrashData( * Builds the non-fatal record for a backgrounded main-thread block, with a * [buildBlockFingerprint] summary embedded in the message. */ +// Appended last so dashboards grouping on the message prefix keep grouping. +private fun timelineSuffix(startupTimeline: String?): String = startupTimeline?.let { " | $it" }.orEmpty() + internal fun buildBackgroundBlockCrashData( threadName: String, stackTrace: Array, 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, diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/logging/logger/android/AndroidLogAnrDetector.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/logging/logger/android/AndroidLogAnrDetector.kt index a32900e2a..d89063e3d 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/logging/logger/android/AndroidLogAnrDetector.kt +++ b/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}") diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt index adbc36708..3c96a8bda 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt @@ -19,6 +19,7 @@ import com.onesignal.common.services.IServiceProvider import com.onesignal.common.services.ServiceBuilder import com.onesignal.common.services.ServiceProvider import com.onesignal.common.threading.OneSignalDispatchers +import com.onesignal.common.threading.StartupTimeline import com.onesignal.common.threading.suspendifyOnIO import com.onesignal.core.CoreModule import com.onesignal.core.internal.application.IApplicationService @@ -391,7 +392,9 @@ internal class OneSignalImp : IOneSignal, // Dispatch init asynchronously so this method never blocks the caller. Callers that // need to wait (accessors, login, logout) will block via suspendCompletion. + StartupTimeline.initQueued() suspendifyOnIO { + StartupTimeline.initStarted() internalInit(context, appId) } return true @@ -550,8 +553,10 @@ internal class OneSignalImp : IOneSignal, } // Intentionally dispatcher-less: wait on the calling thread's own event loop so resuming // when init completes never depends on a free worker in a busy pool. - runBlocking { - waitUntilInitInternal(operationName) + StartupTimeline.mainWaitingForInit { + runBlocking { + waitUntilInitInternal(operationName) + } } } @@ -569,10 +574,13 @@ internal class OneSignalImp : IOneSignal, require(terminalState == InitState.SUCCESS || terminalState == InitState.FAILED) { "completeInit requires a terminal state, got $terminalState" } + StartupTimeline.initEnded(terminalState.name.lowercase()) synchronized(initLock) { initState = terminalState suspendCompletion.complete(Unit) } + // After completing, so a main thread still blocked in waitForInit is counted up to now. + if (StartupTimeline.claimReport()) Logging.info("OneSignal: ${StartupTimeline.summary()}") } /** @@ -807,7 +815,9 @@ internal class OneSignalImp : IOneSignal, // Only the caller that actually runs init needs the IO dispatcher, to keep its disk // and network work off the calling thread. + StartupTimeline.initQueued() return withContext(ioDispatcher) { + StartupTimeline.initStarted() internalInit(context, appId) } } diff --git a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt new file mode 100644 index 000000000..7b62d1b06 --- /dev/null +++ b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt @@ -0,0 +1,185 @@ +package com.onesignal.common.threading + +import android.os.Looper +import br.com.colman.kotest.android.extensions.robolectric.RobolectricTest +import com.onesignal.debug.ILogListener +import com.onesignal.debug.internal.crash.buildAnrCrashData +import com.onesignal.debug.internal.crash.buildBackgroundBlockCrashData +import com.onesignal.debug.internal.logging.Logging +import com.onesignal.internal.InitState +import com.onesignal.internal.OneSignalImp +import io.kotest.core.spec.style.FunSpec +import io.kotest.matchers.shouldBe +import io.kotest.matchers.string.shouldContain +import io.kotest.matchers.string.shouldEndWith +import io.kotest.matchers.string.shouldNotContain +import kotlinx.coroutines.CompletableDeferred +import org.robolectric.shadows.ShadowSystemClock +import java.time.Duration +import java.util.concurrent.CopyOnWriteArrayList +import kotlin.concurrent.thread + +@RobolectricTest +class StartupTimelineTests : FunSpec({ + beforeTest { + StartupTimeline.resetForTest() + } + + afterTest { + OneSignalDispatchers.resetBootstrapInputsForTest() + OneSignalDispatchers.resetForTest() + StartupTimeline.resetForTest() + } + + test("tests run on the main looper, which the main-thread counters depend on") { + (Looper.myLooper() == Looper.getMainLooper()) shouldBe true + } + + test("each step is reported once, and only the first mark counts") { + StartupTimeline.poolsChosen("lazy", "off, no cache yet") + advance(10) + StartupTimeline.poolsChosen("bootstrap", "on") + StartupTimeline.initQueued() + advance(30) + StartupTimeline.initStarted() + advance(200) + StartupTimeline.initEnded("success") + + val summary = StartupTimeline.summary() + summary shouldContain "pools=lazy choice=\"off, no cache yet\"" + field(summary, "init_started_ms") - field(summary, "init_queued_ms") shouldBe 30 + field(summary, "init_ended_ms") - field(summary, "init_started_ms") shouldBe 200 + summary shouldContain "init_result=success" + } + + test("lanes are ready only when every lane is, and a lane reported twice does not count twice") { + StartupTimeline.poolsChosen("lazy", "test") + StartupTimeline.laneReady(Lane.INGRESS) + StartupTimeline.laneReady(Lane.IO) + StartupTimeline.laneReady(Lane.IO) + StartupTimeline.laneReady(Lane.DEFAULT) + StartupTimeline.summary() shouldContain "lanes_ready_ms=-" + + advance(5) + StartupTimeline.laneReady(Lane.SERIAL_IO) + val summary = StartupTimeline.summary() + field(summary, "lanes_ready_ms") - field(summary, "io_ready_ms") shouldBe 5 + } + + test("main blocked on init is counted, including a wait still going") { + StartupTimeline.mainWaitingForInit { + advance(400) + StartupTimeline.summary() shouldContain "main_wait_ongoing=true" + field(StartupTimeline.summary(), "main_wait_ms") shouldBe 400 + } + val summary = StartupTimeline.summary() + summary shouldNotContain "main_wait_ongoing" + field(summary, "main_wait_ms") shouldBe 400 + field(summary, "main_waits") shouldBe 1 + } + + test("a background thread waiting on init is not main blocked") { + thread { StartupTimeline.mainWaitingForInit { advance(400) } }.join() + + field(StartupTimeline.summary(), "main_waits") shouldBe 0 + } + + test("a lane build nested in a scope build on main counts once") { + StartupTimeline.mainBuildingLane { + advance(100) + StartupTimeline.mainBuildingLane { advance(50) } + } + + field(StartupTimeline.summary(), "main_lane_build_ms") shouldBe 150 + } + + test("with lazy pools, main building the first lane is counted and every lane reports ready") { + OneSignalDispatchers.bootstrapEnabledForTest = false + OneSignalDispatchers.unpublishPoolsForTest() + DispatcherTestHooks.beforeLaneCreate = { advance(40) } + + OneSignalDispatchers.launchOnIO { } + + val summary = StartupTimeline.summary() + summary shouldContain "pools=lazy" + (field(summary, "main_lane_build_ms") >= 40) shouldBe true + summary shouldNotContain "io_ready_ms=-" + } + + test("with bootstrap pools, main never builds a lane") { + OneSignalDispatchers.bootstrapEnabledForTest = true + OneSignalDispatchers.unpublishPoolsForTest() + DispatcherTestHooks.beforeLaneCreate = { advance(40) } + + OneSignalDispatchers.launchOnIO { } + OneSignalDispatchers.prewarm(null) + OneSignalDispatchers.awaitReadyForTest() shouldBe true + + val summary = StartupTimeline.summary() + summary shouldContain "pools=bootstrap" + field(summary, "main_lane_build_ms") shouldBe 0 + summary shouldNotContain "lanes_ready_ms=-" + } + + test("init end logs the timeline once, counting main still blocked in waitForInit") { + val os = OneSignalImp() + os.setField("initState", InitState.IN_PROGRESS) + os.setField("suspendCompletion", CompletableDeferred()) + val completeInit = os.method("completeInit", InitState::class.java) + val lines = CopyOnWriteArrayList() + val listener = ILogListener { if (it.entry.contains("startup_timeline")) lines += it.entry } + Logging.addListener(listener) + try { + thread { + Thread.sleep(100) + advance(300) + completeInit.invoke(os, InitState.SUCCESS) + } + os.method("waitForInit", String::class.java).invoke(os, null) + completeInit.invoke(os, InitState.SUCCESS) + } finally { + Logging.removeListener(listener) + } + + lines.size shouldBe 1 + lines[0] shouldContain "init_result=success" + lines[0] shouldContain "main_waits=1 main_wait_ongoing=true" + (field(lines[0], "main_wait_ms") >= 300) shouldBe true + } + + test("ANR records carry the timeline during startup, after the existing message") { + StartupTimeline.initQueued() + val timeline = StartupTimeline.anrSummary()!! + + buildAnrCrashData("main", emptyArray(), 6_000L, timeline).exceptionMessage shouldBe + "Application Not Responding: Main thread blocked for 6000ms | $timeline" + buildBackgroundBlockCrashData("main", emptyArray(), 11_000L, timeline).exceptionMessage shouldEndWith " | $timeline" + buildAnrCrashData("main", emptyArray(), 6_000L).exceptionMessage shouldNotContain "startup_timeline" + } + + test("an ANR long after init ended carries no timeline") { + StartupTimeline.initEnded("success") + advance(29_000) + (StartupTimeline.anrSummary() != null) shouldBe true + + advance(2_000) + StartupTimeline.anrSummary() shouldBe null + } +}) + +private fun OneSignalImp.setField( + name: String, + value: Any, +) = OneSignalImp::class.java.getDeclaredField(name).apply { isAccessible = true }.set(this, value) + +private fun OneSignalImp.method( + name: String, + vararg types: Class<*>, +) = OneSignalImp::class.java.getDeclaredMethod(name, *types).apply { isAccessible = true } + +private fun advance(ms: Long) = ShadowSystemClock.advanceBy(Duration.ofMillis(ms)) + +private fun field( + summary: String, + name: String, +): Long = Regex("$name=(-?\\d+)").find(summary)!!.groupValues[1].toLong() From 40ff38129a8ae4aab22cbf047c9381b82d6e0323 Mon Sep 17 00:00:00 2001 From: AR Abdul Azeez Date: Thu, 22 Oct 2026 14:18:18 -0500 Subject: [PATCH 2/3] fix: harden the startup timeline per review - A throwing log listener can no longer fail a finished init. - A retry after a failed init resets the init marks and reports again (init_attempts). - Resolve the IO lane before init_queued so lazy lane builds are not counted as queue wait. - Only an in-progress init counts as main blocked; main wait total and ongoing read together. - ANR cutoff is 30s inclusive; fall back to nanoTime when SystemClock is unavailable. - Reset the timeline between specs; fix the racy init test; tidy KDocs. Co-authored-by: Cursor --- .../common/threading/StartupTimeline.kt | 82 +++++++++++++------ .../debug/internal/crash/AnrCheckEvaluator.kt | 6 +- .../com/onesignal/internal/OneSignalImp.kt | 29 +++++-- .../onesignal/OneSignalTestProjectConfig.kt | 2 + .../common/threading/StartupTimelineTests.kt | 63 ++++++++++++-- 5 files changed, 139 insertions(+), 43 deletions(-) diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt index 87d2adfd7..b8fcf0916 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt @@ -9,13 +9,13 @@ 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. Splits a - * slow start into waiting for a thread (init queued to started) versus init's own work (started to - * ended), and records how much of that main spent blocked. Marks are first-write-wins and lock-free. + * 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 @@ -29,17 +29,21 @@ internal object StartupTimeline { 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 mainWaitTotal = AtomicLong(0) - private val mainWaits = AtomicInteger(0) - private val mainWaitSince = AtomicLong(UNSET) - private val mainLaneBuild = AtomicLong(0) private val reported = AtomicBoolean(false) + // Total and in-progress wait change together, so a summary never drops or double counts a wait. + private val mainWaitLock = Any() + private var mainWaitTotal = 0L + private var mainWaits = 0 + private var mainWaitSince = UNSET + private val mainLaneBuild = AtomicLong(0) + // Touched only on main: a scope build reads the dispatcher, and that must not count twice. private var mainTimingLane = false @@ -56,6 +60,7 @@ internal object StartupTimeline { 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) @@ -70,6 +75,14 @@ internal object StartupTimeline { } } + /** 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()) } @@ -86,19 +99,24 @@ internal object StartupTimeline { fun mainWaitingForInit(block: () -> T): T { if (!isMainThread()) return block() val start = now() - mainWaitSince.set(start) - mainWaits.incrementAndGet() + synchronized(mainWaitLock) { + mainWaitSince = start + mainWaits++ + } try { return block() } finally { - mainWaitSince.set(UNSET) - mainWaitTotal.addAndGet(now() - start) + val end = now() + synchronized(mainWaitLock) { + mainWaitSince = UNSET + mainWaitTotal += end - start + } } } /** Runs [block], counting its duration as main building (or waiting on) a lane when called on main. */ fun mainBuildingLane(block: () -> T): T { - if (mainTimingLane || !isMainThread()) return block() + if (!isMainThread() || mainTimingLane) return block() mainTimingLane = true val start = now() try { @@ -109,35 +127,44 @@ internal object StartupTimeline { } } - /** True once per process, for whoever logs the timeline. */ + /** True once per init attempt that reaches the end, for whoever logs the timeline. */ fun claimReport(): Boolean = reported.compareAndSet(false, true) - /** Every step as milliseconds since process start; "-" for a step not reached. */ + /** + * 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 ongoing = if (mainWaitSince.get() != UNSET) " main_wait_ongoing=true" else "" + val (waitMs, waits, ongoing) = mainWait() + val ongoingField = if (ongoing) " main_wait_ongoing=true" else "" 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_queued_ms=${at(initQueued.get())} init_started_ms=${at(initStarted.get())} " + - "init_ended_ms=${at(initEnded.get())} init_result=$initResult main_wait_ms=${mainWaitMs()} " + - "main_waits=${mainWaits.get()}$ongoing main_lane_build_ms=${mainLaneBuild.get()} origin=${originName()}" + "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=$waitMs main_waits=$waits$ongoingField main_lane_build_ms=${mainLaneBuild.get()} " + + "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 + if (ended != UNSET && now() - ended >= ANR_RELEVANCE_MS) return null return summary() } internal fun resetForTest() { processStart.set(if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) Process.getStartUptimeMillis() else UNSET) - listOf(poolsChosen, ioReady, lanesReady, initQueued, initStarted, initEnded, mainWaitSince).forEach { it.set(UNSET) } - mainWaitTotal.set(0) + listOf(poolsChosen, ioReady, lanesReady, initQueued, initStarted, initEnded).forEach { it.set(UNSET) } + synchronized(mainWaitLock) { + mainWaitTotal = 0 + mainWaits = 0 + mainWaitSince = UNSET + } mainLaneBuild.set(0) readyLaneBits.set(0) - mainWaits.set(0) + initAttempts.set(0) pools = "unknown" choice = "unknown" initResult = "pending" @@ -149,10 +176,11 @@ internal object StartupTimeline { // 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" - private fun mainWaitMs(): Long { - val since = mainWaitSince.get() - return mainWaitTotal.get() + if (since != UNSET) now() - since else 0 - } + private fun mainWait(): Triple = + synchronized(mainWaitLock) { + val ongoing = mainWaitSince != UNSET + Triple(mainWaitTotal + if (ongoing) now() - mainWaitSince else 0, mainWaits, ongoing) + } // Marks run inside lane builds and init, so a missing Android runtime (plain JVM tests) must not throw. @Suppress("SwallowedException") @@ -160,7 +188,7 @@ internal object StartupTimeline { try { SystemClock.uptimeMillis() } catch (_: RuntimeException) { - UNSET + System.nanoTime() / NANOS_PER_MS } @Suppress("SwallowedException") diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt index 720f5358f..511074bd6 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/debug/internal/crash/AnrCheckEvaluator.kt @@ -232,13 +232,13 @@ 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. */ -// Appended last so dashboards grouping on the message prefix keep grouping. -private fun timelineSuffix(startupTimeline: String?): String = startupTimeline?.let { " | $it" }.orEmpty() - internal fun buildBackgroundBlockCrashData( threadName: String, stackTrace: Array, diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt index 3c96a8bda..5f98be681 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/internal/OneSignalImp.kt @@ -371,6 +371,7 @@ internal class OneSignalImp : IOneSignal, // Fresh latch for this init attempt -- prevents retry-after-FAILED waiters from // observing the prior init's already-completed deferred. suspendCompletion = CompletableDeferred() + StartupTimeline.initAttempt() } // Tight try/catch around the only step that can throw synchronously *before* the @@ -392,6 +393,8 @@ internal class OneSignalImp : IOneSignal, // Dispatch init asynchronously so this method never blocks the caller. Callers that // need to wait (accessors, login, logout) will block via suspendCompletion. + // Resolve IO first: lazy pools build it on the caller, which is main_lane_build_ms, not init's queue wait. + OneSignalDispatchers.IO StartupTimeline.initQueued() suspendifyOnIO { StartupTimeline.initStarted() @@ -553,11 +556,9 @@ internal class OneSignalImp : IOneSignal, } // Intentionally dispatcher-less: wait on the calling thread's own event loop so resuming // when init completes never depends on a free worker in a busy pool. - StartupTimeline.mainWaitingForInit { - runBlocking { - waitUntilInitInternal(operationName) - } - } + val wait = { runBlocking { waitUntilInitInternal(operationName) } } + // Only an in-progress init can block; NOT_STARTED and FAILED throw right away. + if (initState == InitState.IN_PROGRESS) StartupTimeline.mainWaitingForInit(wait) else wait() } /** @@ -579,8 +580,17 @@ internal class OneSignalImp : IOneSignal, initState = terminalState suspendCompletion.complete(Unit) } - // After completing, so a main thread still blocked in waitForInit is counted up to now. - if (StartupTimeline.claimReport()) Logging.info("OneSignal: ${StartupTimeline.summary()}") + reportStartupTimeline() + } + + // After completing, so a main thread still blocked in waitForInit is counted up to now. + // Must not throw: log listeners are customer code, and a throw here would fail a finished init. + @Suppress("TooGenericExceptionCaught", "SwallowedException") + private fun reportStartupTimeline() { + try { + if (StartupTimeline.claimReport()) Logging.info("OneSignal: ${StartupTimeline.summary()}") + } catch (_: RuntimeException) { + } } /** @@ -791,6 +801,7 @@ internal class OneSignalImp : IOneSignal, initState = InitState.IN_PROGRESS // Fresh latch for this init attempt. suspendCompletion = CompletableDeferred() + StartupTimeline.initAttempt() // Only the call that actually starts init owns the failure-attribution exception. // Re-entrant callers must not overwrite it -- otherwise the failure stack trace // would point at the SyncJobService coroutine instead of the original initiator. @@ -815,8 +826,10 @@ internal class OneSignalImp : IOneSignal, // Only the caller that actually runs init needs the IO dispatcher, to keep its disk // and network work off the calling thread. + // Resolved before initQueued, for the same reason as in the synchronous initWithContext. + val dispatcher = ioDispatcher StartupTimeline.initQueued() - return withContext(ioDispatcher) { + return withContext(dispatcher) { StartupTimeline.initStarted() internalInit(context, appId) } diff --git a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/OneSignalTestProjectConfig.kt b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/OneSignalTestProjectConfig.kt index adfd15b6e..38181907e 100644 --- a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/OneSignalTestProjectConfig.kt +++ b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/OneSignalTestProjectConfig.kt @@ -2,6 +2,7 @@ package com.onesignal import com.onesignal.common.threading.DispatcherTestHooks import com.onesignal.common.threading.OneSignalDispatchers +import com.onesignal.common.threading.StartupTimeline import io.kotest.core.config.AbstractProjectConfig import io.kotest.core.extensions.Extension import io.kotest.core.listeners.AfterSpecListener @@ -45,4 +46,5 @@ private fun resetDispatchers() { DispatcherTestHooks.reset() OneSignalDispatchers.resetBootstrapInputsForTest() OneSignalDispatchers.resetForTest() + StartupTimeline.resetForTest() } diff --git a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt index 7b62d1b06..42f9a1eeb 100644 --- a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt +++ b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt @@ -131,7 +131,7 @@ class StartupTimelineTests : FunSpec({ Logging.addListener(listener) try { thread { - Thread.sleep(100) + awaitUntil { StartupTimeline.summary().contains("main_wait_ongoing=true") } advance(300) completeInit.invoke(os, InitState.SUCCESS) } @@ -143,10 +143,52 @@ class StartupTimelineTests : FunSpec({ lines.size shouldBe 1 lines[0] shouldContain "init_result=success" - lines[0] shouldContain "main_waits=1 main_wait_ongoing=true" + field(lines[0], "main_waits") shouldBe 1 (field(lines[0], "main_wait_ms") >= 300) shouldBe true } + test("a log listener that throws on the timeline does not fail init") { + val os = OneSignalImp() + os.setField("initState", InitState.IN_PROGRESS) + os.setField("suspendCompletion", CompletableDeferred()) + val listener = ILogListener { if (it.entry.contains("startup_timeline")) throw IllegalStateException("customer") } + Logging.addListener(listener) + try { + os.method("completeInit", InitState::class.java).invoke(os, InitState.SUCCESS) + } finally { + Logging.removeListener(listener) + } + + os.getField("initState") shouldBe InitState.SUCCESS + } + + test("waitForInit before init started is not counted as main blocked") { + val os = OneSignalImp() + + runCatching { os.method("waitForInit", String::class.java).invoke(os, null) }.isFailure shouldBe true + + field(StartupTimeline.summary(), "main_waits") shouldBe 0 + } + + test("a retry after a failed init is timed and reported as its own attempt") { + StartupTimeline.initAttempt() + StartupTimeline.initQueued() + StartupTimeline.initStarted() + StartupTimeline.initEnded("failed") + StartupTimeline.claimReport() shouldBe true + + advance(1_000) + StartupTimeline.initAttempt() + StartupTimeline.summary() shouldContain "init_attempts=2 init_queued_ms=- init_started_ms=- init_ended_ms=- init_result=pending" + StartupTimeline.initQueued() + StartupTimeline.initStarted() + StartupTimeline.initEnded("success") + + StartupTimeline.summary() shouldContain "init_result=success" + StartupTimeline.claimReport() shouldBe true + StartupTimeline.claimReport() shouldBe false + } + test("ANR records carry the timeline during startup, after the existing message") { StartupTimeline.initQueued() val timeline = StartupTimeline.anrSummary()!! @@ -157,16 +199,27 @@ class StartupTimelineTests : FunSpec({ buildAnrCrashData("main", emptyArray(), 6_000L).exceptionMessage shouldNotContain "startup_timeline" } - test("an ANR long after init ended carries no timeline") { + test("an ANR 30 seconds or more after init ended carries no timeline") { StartupTimeline.initEnded("success") - advance(29_000) + advance(29_999) (StartupTimeline.anrSummary() != null) shouldBe true - advance(2_000) + advance(1) StartupTimeline.anrSummary() shouldBe null } }) +private fun awaitUntil(condition: () -> Boolean) { + val deadline = System.nanoTime() + Duration.ofSeconds(10).toNanos() + while (!condition()) { + check(System.nanoTime() < deadline) { "condition not met in 10s" } + Thread.sleep(5) + } +} + +private fun OneSignalImp.getField(name: String): Any? = + OneSignalImp::class.java.getDeclaredField(name).apply { isAccessible = true }.get(this) + private fun OneSignalImp.setField( name: String, value: Any, From 4f70c776272824e8c7daa674c617eaefcde4a575 Mon Sep 17 00:00:00 2001 From: AR Abdul Azeez Date: Thu, 22 Oct 2026 14:25:13 -0500 Subject: [PATCH 3/3] fix: show in-progress lane builds and mark the pool choice before publishing - main_lane_build_ms counts a build still going on main (main_lane_build_ongoing), with the same consistent read as main_wait_ms. - poolsChosen is marked inside poolsLock before poolsRef is published, so no mark can precede the API <24 origin. - Guard Process.getStartUptimeMillis in the object initializer. Co-authored-by: Cursor --- .../common/threading/OneSignalDispatchers.kt | 9 +- .../common/threading/StartupTimeline.kt | 98 ++++++++++++------- .../common/threading/StartupTimelineTests.kt | 10 ++ 3 files changed, 77 insertions(+), 40 deletions(-) diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt index ae7b8e74d..86a5e06ab 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/OneSignalDispatchers.kt @@ -55,10 +55,15 @@ 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 (published == null) StartupTimeline.poolsChosen(choice.mode, choice.detail) if (!Thread.holdsLock(poolsLock)) recordChoice(choice) return published ?: choice.pools } diff --git a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt index b8fcf0916..dabf6c927 100644 --- a/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt +++ b/OneSignalSDK/onesignal/core/src/main/java/com/onesignal/common/threading/StartupTimeline.kt @@ -37,12 +37,8 @@ internal object StartupTimeline { @Volatile private var initResult = "pending" private val reported = AtomicBoolean(false) - // Total and in-progress wait change together, so a summary never drops or double counts a wait. - private val mainWaitLock = Any() - private var mainWaitTotal = 0L - private var mainWaits = 0 - private var mainWaitSince = UNSET - private val mainLaneBuild = AtomicLong(0) + 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 @@ -98,31 +94,16 @@ internal object StartupTimeline { /** Runs [block], counting its duration as main blocked on init when called on main. */ fun mainWaitingForInit(block: () -> T): T { if (!isMainThread()) return block() - val start = now() - synchronized(mainWaitLock) { - mainWaitSince = start - mainWaits++ - } - try { - return block() - } finally { - val end = now() - synchronized(mainWaitLock) { - mainWaitSince = UNSET - mainWaitTotal += end - start - } - } + return mainWait.time(block) } /** Runs [block], counting its duration as main building (or waiting on) a lane when called on main. */ fun mainBuildingLane(block: () -> T): T { if (!isMainThread() || mainTimingLane) return block() mainTimingLane = true - val start = now() try { - return block() + return mainLaneBuild.time(block) } finally { - mainLaneBuild.addAndGet(now() - start) mainTimingLane = false } } @@ -137,14 +118,14 @@ internal object StartupTimeline { fun summary(): String { val origin = origin() fun at(value: Long) = if (value == UNSET || origin == UNSET) "-" else (value - origin).toString() - val (waitMs, waits, ongoing) = mainWait() - val ongoingField = if (ongoing) " main_wait_ongoing=true" else "" + 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=$waitMs main_waits=$waits$ongoingField main_lane_build_ms=${mainLaneBuild.get()} " + - "origin=${originName()}" + "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. */ @@ -155,14 +136,10 @@ internal object StartupTimeline { } internal fun resetForTest() { - processStart.set(if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) Process.getStartUptimeMillis() else UNSET) + processStart.set(processStartUptime()) listOf(poolsChosen, ioReady, lanesReady, initQueued, initStarted, initEnded).forEach { it.set(UNSET) } - synchronized(mainWaitLock) { - mainWaitTotal = 0 - mainWaits = 0 - mainWaitSince = UNSET - } - mainLaneBuild.set(0) + mainWait.reset() + mainLaneBuild.reset() readyLaneBits.set(0) initAttempts.set(0) pools = "unknown" @@ -176,10 +153,13 @@ internal object StartupTimeline { // 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" - private fun mainWait(): Triple = - synchronized(mainWaitLock) { - val ongoing = mainWaitSince != UNSET - Triple(mainWaitTotal + if (ongoing) now() - mainWaitSince else 0, mainWaits, ongoing) + // 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. @@ -198,4 +178,46 @@ internal object StartupTimeline { } 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 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 + } + } } diff --git a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt index 42f9a1eeb..58e0f760a 100644 --- a/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt +++ b/OneSignalSDK/onesignal/core/src/test/java/com/onesignal/common/threading/StartupTimelineTests.kt @@ -93,6 +93,16 @@ class StartupTimelineTests : FunSpec({ field(StartupTimeline.summary(), "main_lane_build_ms") shouldBe 150 } + test("a lane build still going on main is counted, so an ANR during it shows the build") { + StartupTimeline.mainBuildingLane { + advance(100) + val summary = StartupTimeline.summary() + summary shouldContain "main_lane_build_ongoing=true" + field(summary, "main_lane_build_ms") shouldBe 100 + } + StartupTimeline.summary() shouldNotContain "main_lane_build_ongoing" + } + test("with lazy pools, main building the first lane is counted and every lane reports ready") { OneSignalDispatchers.bootstrapEnabledForTest = false OneSignalDispatchers.unpublishPoolsForTest()