Use onCreate invocation to denote Activity init start time (#820)

## Goal

In production, we are seeing a small minority of cases where there is a big gap between when onActivityPreCreated was invoked and when onActivityStart() was invoked. This could be a case of these being two separate activities or instances, or there are cases when the activity creation and starting stage can be paused.

In order to improve the trace and diagnose what's really going on, I changed the trace to use the onCreate time rather than the preCreate time, which is how it works on Android 9 or earlier, as preCreate is not a thing on those API versions. We also explicitly log the pre-create and post-create times as attributes for further debugging if this doesn't end up addressing the problem.

As well as the fix, I tweaked the implementation of the trace logging component (AppStartupTraceEmitter) so it's more streamlined, logs the name of the activity being displayed, removed the emb- prefix on attributes, and extracted the public interface into an interface so i can more easily test the StartupTracker by faking that.

In additional, I added more tests to verify the startup trace being logged properly as well as the `StartupTracker` consuming lifecycle events properly. I couldn't add test to verify the render due to the limitations of Roboletric, so I've left that alone for now. I've spent way too much time on this already....

## Testing

Updated Roboletric to the latest stable version so I can test with U as well as added the modified the appropriate tests.

embrace-android-sdk/build.gradle

@@ -97,7 +97,7 @@ dependencies {
  testImplementation "io.mockk:mockk:1.12.2"
  testImplementation "androidx.test:core:1.4.0"
  testImplementation "androidx.test.ext:junit:1.1.3"
- testImplementation "org.robolectric:robolectric:4.10.3"
+ testImplementation "org.robolectric:robolectric:4.12.1"
  testImplementation project(path: ":embrace-android-sdk")
  testImplementation "com.squareup.okhttp3:mockwebserver:4.9.3"
  testImplementation("com.google.protobuf:protobuf-java:3.24.0")

embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/AppStartupDataCollector.kt

@@ -0,0 +1,54 @@
+package io.embrace.android.embracesdk.capture.startup
+
+/**
+ * Collects relevant information during app startup to be used to produce telemetry about the startup workflow.
+ *
+ * Due to differences in behaviour between platform versions and various startup scenarios, you cannot assume that these methods
+ * will be invoked in any order or at all. Implementations need to take into account that fact when using the underlying data.
+ */
+internal interface AppStartupDataCollector {
+ /**
+ * Set the time when the application object initialization was started
+ */
+ fun applicationInitStart(timestampMs: Long? = null)
+
+ /**
+ * Set the time when the application object initialization has finished
+ */
+ fun applicationInitEnd(timestampMs: Long? = null)
+
+ /**
+ * Set the time just prior to the creation of the Activity whose rendering will denote the end of the startup workflow
+ */
+ fun startupActivityPreCreated(timestampMs: Long? = null)
+
+ /**
+ * Set the time for the start of the initialization of the Activity whose rendering will denote the end of the startup workflow
+ */
+ fun startupActivityInitStart(timestampMs: Long? = null)
+
+ /**
+ * Set the time just after the creation of the Activity whose rendering will denote the end of the startup workflow
+ */
+ fun startupActivityPostCreated(timestampMs: Long? = null)
+
+ /**
+ * Set the time for the end of the initialization of the Activity whose rendering will denote the end of the startup workflow
+ */
+ fun startupActivityInitEnd(timestampMs: Long? = null)
+
+ /**
+ * Set the time for when the startup Activity begins to render as well as its name
+ */
+ fun startupActivityResumed(activityName: String, timestampMs: Long? = null)
+
+ /**
+ * Set the time for when the startup Activity has finished rendering its first frame as well as its name
+ */
+ fun firstFrameRendered(activityName: String, timestampMs: Long? = null)
+
+ /**
+ * Set an arbitrary time interval during startup that is of note
+ */
+ fun addTrackedInterval(name: String, startTimeMs: Long, endTimeMs: Long)
+}

embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/AppStartupTraceEmitter.kt

@@ -4,11 +4,11 @@ import android.os.Build.VERSION_CODES
 import android.os.Process
 import io.embrace.android.embracesdk.internal.clock.nanosToMillis
 import io.embrace.android.embracesdk.internal.spans.SpanService
-import io.embrace.android.embracesdk.internal.spans.toEmbraceAttributeName
 import io.embrace.android.embracesdk.internal.utils.Provider
 import io.embrace.android.embracesdk.internal.utils.VersionChecker
 import io.embrace.android.embracesdk.logging.EmbLogger
 import io.embrace.android.embracesdk.spans.EmbraceSpan
+import io.embrace.android.embracesdk.spans.PersistableEmbraceSpan
 import io.embrace.android.embracesdk.worker.BackgroundWorker
 import io.opentelemetry.sdk.common.Clock
 import java.util.concurrent.ConcurrentLinkedQueue
@@ -41,7 +41,7 @@ internal class AppStartupTraceEmitter(
  private val backgroundWorker: BackgroundWorker,
  private val versionChecker: VersionChecker,
  private val logger: EmbLogger
-) {
+) : AppStartupDataCollector {
  private val processCreateRequestedMs: Long?
  private val processCreatedMs: Long?
  private val additionalTrackedIntervals = ConcurrentLinkedQueue<TrackedInterval>()
@@ -66,9 +66,18 @@ internal class AppStartupTraceEmitter(
  @Volatile
  private var applicationInitEndMs: Long? = null
 
+ @Volatile
+ private var startupActivityName: String? = null
+
+ @Volatile
+ private var startupActivityPreCreatedMs: Long? = null
+
  @Volatile
  private var startupActivityInitStartMs: Long? = null
 
+ @Volatile
+ private var startupActivityPostCreatedMs: Long? = null
+
  @Volatile
  private var startupActivityInitEndMs: Long? = null
 
@@ -81,44 +90,55 @@ internal class AppStartupTraceEmitter(
  private val startupRecorded = AtomicBoolean(false)
  private val endWithFrameDraw: Boolean = versionChecker.isAtLeast(VERSION_CODES.Q)
 
- fun applicationInitStart(timestampMs: Long? = null) {
+ override fun applicationInitStart(timestampMs: Long?) {
  applicationInitStartMs = timestampMs ?: nowMs()
  }
 
- fun applicationInitEnd(timestampMs: Long? = null) {
+ override fun applicationInitEnd(timestampMs: Long?) {
  applicationInitEndMs = timestampMs ?: nowMs()
  }
 
- fun startupActivityInitStart(timestampMs: Long? = null) {
- if (startupActivityInitStartMs == null) {
- startupActivityInitStartMs = timestampMs ?: nowMs()
- }
+ override fun startupActivityPreCreated(timestampMs: Long?) {
+ startupActivityPreCreatedMs = timestampMs ?: nowMs()
  }
 
- fun startupActivityInitEnd(timestampMs: Long? = null) {
+ override fun startupActivityInitStart(timestampMs: Long?) {
+ startupActivityInitStartMs = timestampMs ?: nowMs()
+ }
+
+ override fun startupActivityPostCreated(timestampMs: Long?) {
+ startupActivityPostCreatedMs = timestampMs ?: nowMs()
+ }
+
+ override fun startupActivityInitEnd(timestampMs: Long?) {
  startupActivityInitEndMs = timestampMs ?: nowMs()
  }
 
- fun startupActivityResumed(timestampMs: Long? = null) {
+ override fun startupActivityResumed(activityName: String, timestampMs: Long?) {
+ startupActivityName = activityName
  startupActivityResumedMs = timestampMs ?: nowMs()
  if (!endWithFrameDraw) {
  dataCollectionComplete()
  }
  }
 
- fun firstFrameRendered(timestampMs: Long? = null) {
+ override fun firstFrameRendered(activityName: String, timestampMs: Long?) {
+ startupActivityName = activityName
  firstFrameRenderedMs = timestampMs ?: nowMs()
  if (endWithFrameDraw) {
  dataCollectionComplete()
  }
  }
 
- fun addTrackedInterval(name: String, startTimeMs: Long, endTimeMs: Long) {
+ override fun addTrackedInterval(name: String, startTimeMs: Long, endTimeMs: Long) {
  additionalTrackedIntervals.add(
  TrackedInterval(name = name, startTimeMs = startTimeMs, endTimeMs = endTimeMs)
  )
  }
 
+ /**
+ * Called when app startup is considered complete, i.e. the data can be used and any additional updates can be ignored
+ */
  private fun dataCollectionComplete() {
  if (!startupRecorded.get()) {
  synchronized(startupRecorded) {
@@ -169,17 +189,15 @@ internal class AppStartupTraceEmitter(
  activityInitStartMs = startupActivityInitStartMs,
  activityInitEndMs = startupActivityInitEndMs,
  traceEndTimeMs = traceEndTimeMs,
- processCreateDelay = processCreateDelay(),
  )
  } else {
  startupActivityInitStartMs?.let { startTime ->
  recordWarmTtid(
  traceStartTimeMs = startTime,
  activityInitEndMs = startupActivityInitEndMs,
  traceEndTimeMs = traceEndTimeMs,
- processCreateDelay = processCreateDelay(),
  processToActivityCreateGap = gap,
- sdkStartupDuration = sdkStartupDuration
+ sdkStartupDuration = sdkStartupDuration,
  )
  }
  }
@@ -214,17 +232,15 @@ internal class AppStartupTraceEmitter(
  activityInitStartMs: Long?,
  activityInitEndMs: Long?,
  traceEndTimeMs: Long,
- processCreateDelay: Long?,
  ): EmbraceSpan? {
  return if (!startupRecorded.get()) {
  spanService.startSpan(
  name = "cold-time-to-initial-display",
  startTimeMs = traceStartTimeMs,
  private = false
  )?.apply {
- processCreateDelay?.let { delay ->
- addAttribute("process-create-delay-ms".toEmbraceAttributeName(), delay.toString())
- }
+ addTraceMetadata()
+
  if (stop(endTimeMs = traceEndTimeMs)) {
  startupRecorded.set(true)
  }
@@ -290,7 +306,6 @@ internal class AppStartupTraceEmitter(
  traceStartTimeMs: Long,
  activityInitEndMs: Long?,
  traceEndTimeMs: Long,
- processCreateDelay: Long?,
  processToActivityCreateGap: Long?,
  sdkStartupDuration: Long?,
  ): EmbraceSpan? {
@@ -300,15 +315,15 @@ internal class AppStartupTraceEmitter(
  startTimeMs = traceStartTimeMs,
  private = false,
  )?.apply {
- processCreateDelay?.let { delay ->
- addAttribute("process-create-delay-ms".toEmbraceAttributeName(), delay.toString())
- }
  processToActivityCreateGap?.let { gap ->
- addAttribute("activity-init-gap-ms".toEmbraceAttributeName(), gap.toString())
+ addAttribute("activity-init-gap-ms", gap.toString())
  }
  sdkStartupDuration?.let { duration ->
- addAttribute("embrace-init-duration-ms".toEmbraceAttributeName(), duration.toString())
+ addAttribute("embrace-init-duration-ms", duration.toString())
  }
+
+ addTraceMetadata()
+
  if (stop(endTimeMs = traceEndTimeMs)) {
  startupRecorded.set(true)
  }
@@ -345,6 +360,24 @@ internal class AppStartupTraceEmitter(
 
  private fun nowMs(): Long = clock.now().nanosToMillis()
 
+ private fun PersistableEmbraceSpan.addTraceMetadata() {
+ processCreateDelay()?.let { delay ->
+ addAttribute("process-create-delay-ms", delay.toString())
+ }
+
+ startupActivityName?.let { name ->
+ addAttribute("startup-activity-name", name)
+ }
+
+ startupActivityPreCreatedMs?.let { timeMs ->
+ addAttribute("startup-activity-pre-created-ms", timeMs.toString())
+ }
+
+ startupActivityPostCreatedMs?.let { timeMs ->
+ addAttribute("startup-activity-post-created-ms", timeMs.toString())
+ }
+ }
+
  private data class TrackedInterval(
  val name: String,
  val startTimeMs: Long,

embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/StartupTracker.kt

@@ -36,16 +36,24 @@ import io.embrace.android.embracesdk.logging.EmbLogger
  * that can be found here: https://blog.p-y.wtf/tracking-android-app-launch-in-production. PY's code was adapted and tweaked for use here.
  */
 internal class StartupTracker(
- private val appStartupTraceEmitter: AppStartupTraceEmitter,
+ private val appStartupDataCollector: AppStartupDataCollector,
  private val logger: EmbLogger,
  private val versionChecker: VersionChecker,
 ) : Application.ActivityLifecycleCallbacks {
  private var isFirstDraw = false
  private var nullWindowCallbackErrorLogged = false
+ private var startupActivityId: Int? = null
+
+ override fun onActivityPreCreated(activity: Activity, savedInstanceState: Bundle?) {
+ if (activity.useAsStartupActivity()) {
+ appStartupDataCollector.startupActivityPreCreated()
+ }
+ }
 
  override fun onActivityCreated(activity: Activity, savedInstanceState: Bundle?) {
- if (activity.observeForStartup()) {
- appStartupTraceEmitter.startupActivityInitStart()
+ if (activity.useAsStartupActivity()) {
+ val activityName = activity.localClassName
+ appStartupDataCollector.startupActivityInitStart()
  if (versionChecker.isAtLeast(Build.VERSION_CODES.Q)) {
  if (!isFirstDraw) {
  val window = activity.window
@@ -55,7 +63,7 @@ internal class StartupTracker(
  decorView.onNextDraw {
  if (!isFirstDraw) {
  isFirstDraw = true
- val callback = { appStartupTraceEmitter.firstFrameRendered() }
+ val callback = { appStartupDataCollector.firstFrameRendered(activityName = activityName) }
  decorView.viewTreeObserver.registerFrameCommitCallback(callback)
  }
  }
@@ -69,21 +77,21 @@ internal class StartupTracker(
  }
  }
 
- override fun onActivityPreCreated(activity: Activity, savedInstanceState: Bundle?) {
- if (activity.observeForStartup()) {
- appStartupTraceEmitter.startupActivityInitStart()
+ override fun onActivityPostCreated(activity: Activity, savedInstanceState: Bundle?) {
+ if (activity.useAsStartupActivity()) {
+ appStartupDataCollector.startupActivityPostCreated()
  }
  }
 
  override fun onActivityStarted(activity: Activity) {
- if (activity.observeForStartup()) {
- appStartupTraceEmitter.startupActivityInitEnd()
+ if (activity.isStartupActivity()) {
+ appStartupDataCollector.startupActivityInitEnd()
  }
  }
 
  override fun onActivityResumed(activity: Activity) {
  if (activity.observeForStartup()) {
- appStartupTraceEmitter.startupActivityResumed()
+ appStartupDataCollector.startupActivityResumed(activityName = activity.localClassName)
  }
  }
 
@@ -95,6 +103,34 @@ internal class StartupTracker(
 
  override fun onActivityDestroyed(activity: Activity) {}
 
+ /**
+ * Returns true if the Activity instance is being used as the startup Activity. It will return false if [useAsStartupActivity] has
+ * not been called previously to setup the Activity instance to be used as the startup Activity.
+ */
+ private fun Activity.isStartupActivity(): Boolean {
+ return if (observeForStartup()) {
+ startupActivityId == hashCode()
+ } else {
+ false
+ }
+ }
+
+ /**
+ * Use this Activity instance as the startup activity if appropriate. Return true the current instance is the startup Activity
+ * instance going forward, false otherwise.
+ */
+ private fun Activity.useAsStartupActivity(): Boolean {
+ if (isStartupActivity()) {
+ return true
+ }
+
+ if (observeForStartup()) {
+ startupActivityId = hashCode()
+ }
+
+ return isStartupActivity()
+ }
+
  companion object {
  private class PyNextDrawListener(
  val view: View,

embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/injection/DataCaptureServiceModule.kt

@@ -8,6 +8,7 @@ import io.embrace.android.embracesdk.capture.memory.ComponentCallbackService
 import io.embrace.android.embracesdk.capture.memory.EmbraceMemoryService
 import io.embrace.android.embracesdk.capture.memory.MemoryService
 import io.embrace.android.embracesdk.capture.memory.NoOpMemoryService
+import io.embrace.android.embracesdk.capture.startup.AppStartupDataCollector
 import io.embrace.android.embracesdk.capture.startup.AppStartupTraceEmitter
 import io.embrace.android.embracesdk.capture.startup.StartupService
 import io.embrace.android.embracesdk.capture.startup.StartupServiceImpl
@@ -68,7 +69,7 @@ internal interface DataCaptureServiceModule {
 
  val startupTracker: StartupTracker
 
- val appStartupTraceEmitter: AppStartupTraceEmitter
+ val appStartupDataCollector: AppStartupDataCollector
 }
 
 internal class DataCaptureServiceModuleImpl @JvmOverloads constructor(
@@ -146,7 +147,7 @@ internal class DataCaptureServiceModuleImpl @JvmOverloads constructor(
  )
  }
 
- override val appStartupTraceEmitter: AppStartupTraceEmitter by singleton {
+ override val appStartupDataCollector: AppStartupDataCollector by singleton {
  AppStartupTraceEmitter(
  clock = initModule.openTelemetryClock,
  startupServiceProvider = { startupService },
@@ -159,7 +160,7 @@ internal class DataCaptureServiceModuleImpl @JvmOverloads constructor(
 
  override val startupTracker: StartupTracker by singleton {
  StartupTracker(
- appStartupTraceEmitter = appStartupTraceEmitter,
+ appStartupDataCollector = appStartupDataCollector,
  logger = initModule.logger,
  versionChecker = versionChecker,
  )