diff --git a/embrace-android-api/api/embrace-android-api.api b/embrace-android-api/api/embrace-android-api.api index c8f9726449..e28d3b957b 100644 --- a/embrace-android-api/api/embrace-android-api.api +++ b/embrace-android-api/api/embrace-android-api.api @@ -179,6 +179,27 @@ public abstract interface class io/embrace/android/embracesdk/internal/api/UserA public abstract fun setUsername (Ljava/lang/String;)V } +public abstract interface class io/embrace/android/embracesdk/internal/capture/activity/OpenEvents { + public abstract fun create (ILjava/lang/String;J)V + public abstract fun createEnd (IJ)V + public abstract fun hibernate (ILjava/lang/String;J)V + public abstract fun render (ILjava/lang/String;J)V + public abstract fun renderEnd (IJ)V + public abstract fun resetTrace (ILjava/lang/String;J)V + public abstract fun resume (ILjava/lang/String;J)V + public abstract fun resumeEnd (IJ)V + public abstract fun start (ILjava/lang/String;J)V + public abstract fun startEnd (IJ)V +} + +public final class io/embrace/android/embracesdk/internal/capture/activity/OpenEvents$OpenType : java/lang/Enum { + public static final field COLD Lio/embrace/android/embracesdk/internal/capture/activity/OpenEvents$OpenType; + public static final field HOT Lio/embrace/android/embracesdk/internal/capture/activity/OpenEvents$OpenType; + public final fun getTypeName ()Ljava/lang/String; + public static fun valueOf (Ljava/lang/String;)Lio/embrace/android/embracesdk/internal/capture/activity/OpenEvents$OpenType; + public static fun values ()[Lio/embrace/android/embracesdk/internal/capture/activity/OpenEvents$OpenType; +} + public final class io/embrace/android/embracesdk/internal/network/http/NetworkCaptureData { public fun (Ljava/util/Map;Ljava/lang/String;[BLjava/util/Map;[BLjava/lang/String;)V public synthetic fun (Ljava/util/Map;Ljava/lang/String;[BLjava/util/Map;[BLjava/lang/String;ILkotlin/jvm/internal/DefaultConstructorMarker;)V diff --git a/embrace-android-api/src/main/kotlin/io/embrace/android/embracesdk/internal/capture/activity/OpenEvents.kt b/embrace-android-api/src/main/kotlin/io/embrace/android/embracesdk/internal/capture/activity/OpenEvents.kt new file mode 100644 index 0000000000..c7ba1031ff --- /dev/null +++ b/embrace-android-api/src/main/kotlin/io/embrace/android/embracesdk/internal/capture/activity/OpenEvents.kt @@ -0,0 +1,62 @@ +package io.embrace.android.embracesdk.internal.capture.activity + +/** + * The relevant stages in the lifecycle of Activities pertaining to observing the performance of their loading + */ +public interface OpenEvents { + + /** + * When a previously in-progress Activity Open trace should be abandoned, and that the component managing + * the trace recording should prepare itself to start tracing the opening of a new Activity instance. + */ + public fun resetTrace(instanceId: Int, activityName: String, timestampMs: Long) + + /** + * When the app is no longer in a state where it is trying to open up a new Activity + */ + public fun hibernate(instanceId: Int, activityName: String, timestampMs: Long) + + /** + * When the given Activity is entering the CREATE stage of its lifecycle. + */ + public fun create(instanceId: Int, activityName: String, timestampMs: Long) + + /** + * When the given Activity has exited the CREATE stage of its lifecycle. + */ + public fun createEnd(instanceId: Int, timestampMs: Long) + + /** + * When the given Activity is entering the START stage of its lifecycle. + */ + public fun start(instanceId: Int, activityName: String, timestampMs: Long) + + /** + * When the given Activity has exited the START stage of its lifecycle. + */ + public fun startEnd(instanceId: Int, timestampMs: Long) + + /** + * When the given Activity is entering the RESUME stage of its lifecycle. + */ + public fun resume(instanceId: Int, activityName: String, timestampMs: Long) + + /** + * When the given Activity has exited the RESUME stage of its lifecycle. + */ + public fun resumeEnd(instanceId: Int, timestampMs: Long) + + /** + * When the given Activity's first UI frame starts to be rendered. + */ + public fun render(instanceId: Int, activityName: String, timestampMs: Long) + + /** + * When the given Activity's first UI frame has been displayed. + */ + public fun renderEnd(instanceId: Int, timestampMs: Long) + + public enum class OpenType(public val typeName: String) { + COLD("cold"), HOT("hot") + } +} diff --git a/embrace-android-features/src/main/kotlin/io/embrace/android/embracesdk/internal/capture/activity/OpenTraceEmitter.kt b/embrace-android-features/src/main/kotlin/io/embrace/android/embracesdk/internal/capture/activity/OpenTraceEmitter.kt new file mode 100644 index 0000000000..bdc80949c2 --- /dev/null +++ b/embrace-android-features/src/main/kotlin/io/embrace/android/embracesdk/internal/capture/activity/OpenTraceEmitter.kt @@ -0,0 +1,264 @@ +package io.embrace.android.embracesdk.internal.capture.activity + +import android.app.Application.ActivityLifecycleCallbacks +import android.os.Build +import io.embrace.android.embracesdk.internal.arch.schema.EmbType +import io.embrace.android.embracesdk.internal.spans.PersistableEmbraceSpan +import io.embrace.android.embracesdk.internal.spans.SpanService +import io.embrace.android.embracesdk.internal.utils.VersionChecker +import io.embrace.android.embracesdk.spans.ErrorCode +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.atomic.AtomicReference + +/** + * Observes Activity lifecycle and rendering events to create traces that model the workflow for showing an Activity on screen. + * Depending on the version of Android and the state of the app, the start, end, and intermediate stages of the workflow will use + * timestamps from different events, which affects to preciseness of the measurement. + * + * Trace Start: + * + * - On Android 10+, when [ActivityLifecycleCallbacks.onActivityPostPaused] is fired, denoting that the previous activity has completed + * its [ActivityLifecycleCallbacks.onActivityPaused] callbacks and a new Activity is ready to be created. + * - Android 9 and lower, when [ActivityLifecycleCallbacks.onActivityPaused] is fired, denoting that the previous activity is in the + * process of exiting. This will possibly result in some cleanup work of exiting the previous activity being included in the duration + * of the next trace that is logged. + * + * Trace End: + * + * - Android 10+, when the Activity's first UI frame finishes rendering and is delivered to the screen + * - Android 9 and lower.... TODO + */ +public class OpenTraceEmitter( + private val spanService: SpanService, + private val versionChecker: VersionChecker, +) : OpenEvents { + + private val activeTraces: MutableMap = ConcurrentHashMap() + private val traceIds: MutableMap = ConcurrentHashMap() + private val traceZygoteHolder: AtomicReference = AtomicReference(INITIAL) + + override fun resetTrace(instanceId: Int, activityName: String, timestampMs: Long) { + traceIds[activityName]?.let { existingTraceId -> + if (instanceId != existingTraceId) { + endTrace(instanceId = existingTraceId, timestampMs = timestampMs, errorCode = ErrorCode.USER_ABANDON) + } + } + traceZygoteHolder.set( + OpenTraceZygote( + lastActivityName = activityName, + lastActivityInstanceId = instanceId, + lastActivityPausedTimeMs = timestampMs + ) + ) + } + + override fun hibernate(instanceId: Int, activityName: String, timestampMs: Long) { + if (traceZygoteHolder.get().lastActivityInstanceId == instanceId) { + traceZygoteHolder.set(BACKGROUNDED) + } + } + + override fun create(instanceId: Int, activityName: String, timestampMs: Long) { + startTrace( + openType = OpenEvents.OpenType.COLD, + instanceId = instanceId, + activityName = activityName, + timestampMs = timestampMs + ) + startChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.CREATE + ) + } + + override fun createEnd(instanceId: Int, timestampMs: Long) { + endChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.CREATE + ) + } + + override fun start(instanceId: Int, activityName: String, timestampMs: Long) { + startTrace( + openType = OpenEvents.OpenType.HOT, + instanceId = instanceId, + activityName = activityName, + timestampMs = timestampMs + ) + startChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.START + ) + } + + override fun startEnd(instanceId: Int, timestampMs: Long) { + endChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.START + ) + } + + override fun resume(instanceId: Int, activityName: String, timestampMs: Long) { + if (!hasRenderEvent()) { + endTrace( + instanceId = instanceId, + timestampMs = timestampMs, + ) + } else { + startChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.RESUME + ) + } + traceZygoteHolder.set(READY) + } + + override fun resumeEnd(instanceId: Int, timestampMs: Long) { + endChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.RESUME + ) + } + + override fun render(instanceId: Int, activityName: String, timestampMs: Long) { + startChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.RENDER + ) + } + + override fun renderEnd(instanceId: Int, timestampMs: Long) { + endChildSpan( + instanceId = instanceId, + timestampMs = timestampMs, + lifecycleEvent = LifecycleEvent.RENDER + ) + endTrace( + instanceId = instanceId, + timestampMs = timestampMs, + ) + } + + private fun startTrace( + openType: OpenEvents.OpenType, + instanceId: Int, + activityName: String, + timestampMs: Long + ) { + if (traceZygoteHolder.get() == INITIAL) { + return + } + + if (!activeTraces.containsKey(instanceId)) { + val zygote = traceZygoteHolder.getAndSet(READY) + val startTimeMs = if (zygote.lastActivityPausedTimeMs != -1L) { + zygote.lastActivityPausedTimeMs + } else { + timestampMs + } + + spanService.startSpan( + name = traceName(activityName, openType), + type = EmbType.Performance.ActivityOpen, + startTimeMs = startTimeMs, + )?.let { root -> + if (zygote.lastActivityInstanceId != -1) { + root.addSystemAttribute("last_activity", zygote.lastActivityName) + } + activeTraces[instanceId] = ActivityOpenTrace(root = root, activityName = activityName) + } + } + } + + private fun endTrace(instanceId: Int, timestampMs: Long, errorCode: ErrorCode? = null) { + activeTraces[instanceId]?.let { trace -> + with(trace) { + children.values.filter { it.isRecording }.forEach { span -> + span.stop(endTimeMs = timestampMs, errorCode = errorCode) + } + root.stop(endTimeMs = timestampMs, errorCode = errorCode) + } + activeTraces.remove(instanceId) + } + } + + private fun startChildSpan(instanceId: Int, timestampMs: Long, lifecycleEvent: LifecycleEvent) { + val trace = activeTraces[instanceId] + if (trace != null && !trace.children.containsKey(lifecycleEvent)) { + spanService.startSpan( + name = lifecycleEvent.spanName(trace.activityName), + parent = trace.root, + startTimeMs = timestampMs, + )?.let { newSpan -> + val newChildren = trace.children.plus(lifecycleEvent to newSpan) + activeTraces[instanceId] = trace.copy( + children = newChildren + ) + } + } + } + + private fun endChildSpan(instanceId: Int, timestampMs: Long, lifecycleEvent: LifecycleEvent) { + activeTraces[instanceId]?.let { trace -> + trace.children[lifecycleEvent]?.stop(timestampMs) + } + } + + private fun hasRenderEvent(): Boolean = versionChecker.isAtLeast(Build.VERSION_CODES.Q) + + private fun traceName( + activityName: String, + openType: OpenEvents.OpenType + ): String = "$activityName-${openType.typeName}-open" + + public enum class LifecycleEvent(private val typeName: String) { + CREATE("create"), + START("start"), + RESUME("resume"), + RENDER("render"); + + public fun spanName(activityName: String): String = "$activityName-$typeName" + } + + private data class ActivityOpenTrace( + val activityName: String, + val root: PersistableEmbraceSpan, + val children: Map = ConcurrentHashMap(), + ) + + private data class OpenTraceZygote( + val lastActivityName: String, + val lastActivityInstanceId: Int, + val lastActivityPausedTimeMs: Long, + ) + + private companion object { + const val INVALID_INSTANCE: Int = -1 + const val INVALID_TIME: Long = -1L + + val INITIAL = OpenTraceZygote( + lastActivityName = "NEW_APP_LAUNCH", + lastActivityInstanceId = INVALID_INSTANCE, + lastActivityPausedTimeMs = INVALID_TIME + ) + + val READY = OpenTraceZygote( + lastActivityName = "READY", + lastActivityInstanceId = INVALID_INSTANCE, + lastActivityPausedTimeMs = INVALID_TIME + ) + + val BACKGROUNDED = OpenTraceZygote( + lastActivityName = "BACKGROUNDED", + lastActivityInstanceId = INVALID_INSTANCE, + lastActivityPausedTimeMs = INVALID_TIME + ) + } +} diff --git a/embrace-android-features/src/test/java/io/embrace/android/embracesdk/internal/capture/activity/OpenTraceEmitterTest.kt b/embrace-android-features/src/test/java/io/embrace/android/embracesdk/internal/capture/activity/OpenTraceEmitterTest.kt new file mode 100644 index 0000000000..60a5256daa --- /dev/null +++ b/embrace-android-features/src/test/java/io/embrace/android/embracesdk/internal/capture/activity/OpenTraceEmitterTest.kt @@ -0,0 +1,310 @@ +package io.embrace.android.embracesdk.internal.capture.activity + +import android.os.Build +import androidx.test.ext.junit.runners.AndroidJUnit4 +import io.embrace.android.embracesdk.assertions.assertEmbraceSpanData +import io.embrace.android.embracesdk.fakes.FakeClock +import io.embrace.android.embracesdk.fakes.injection.FakeInitModule +import io.embrace.android.embracesdk.internal.payload.toNewPayload +import io.embrace.android.embracesdk.internal.spans.SpanService +import io.embrace.android.embracesdk.internal.spans.SpanSink +import io.embrace.android.embracesdk.internal.utils.BuildVersionChecker +import io.opentelemetry.api.trace.SpanId +import org.junit.Assert.assertNull +import org.junit.Before +import org.junit.Test +import org.junit.runner.RunWith +import org.robolectric.annotation.Config +import kotlin.math.max +import kotlin.math.min + +@RunWith(AndroidJUnit4::class) +internal class OpenTraceEmitterTest { + private lateinit var clock: FakeClock + private lateinit var spanSink: SpanSink + private lateinit var spanService: SpanService + private lateinit var traceEmitter: OpenTraceEmitter + + @Before + fun setUp() { + clock = FakeClock() + val initModule = FakeInitModule(clock = clock) + spanSink = initModule.openTelemetryModule.spanSink + spanService = initModule.openTelemetryModule.spanService + spanService.initializeService(clock.now()) + clock.tick(100L) + traceEmitter = OpenTraceEmitter( + spanService = spanService, + versionChecker = BuildVersionChecker, + ) + } + + @Config(sdk = [Build.VERSION_CODES.UPSIDE_DOWN_CAKE]) + @Test + fun `verify cold open trace from another activity in U`() { + verifyOpen( + fromBackground = false, + openType = OpenEvents.OpenType.COLD, + firePreAndPost = true, + hasRenderEvent = true, + ) + } + + @Config(sdk = [Build.VERSION_CODES.UPSIDE_DOWN_CAKE]) + @Test + fun `verify cold open trace from background in U`() { + verifyOpen( + fromBackground = true, + openType = OpenEvents.OpenType.COLD, + firePreAndPost = true, + hasRenderEvent = true, + ) + } + + @Config(sdk = [Build.VERSION_CODES.UPSIDE_DOWN_CAKE]) + @Test + fun `verify hot open trace in from background in U`() { + verifyOpen( + fromBackground = true, + openType = OpenEvents.OpenType.HOT, + firePreAndPost = true, + hasRenderEvent = true, + ) + } + + @Config(sdk = [Build.VERSION_CODES.LOLLIPOP]) + @Test + fun `verify cold open trace in from another activity L`() { + verifyOpen( + fromBackground = false, + openType = OpenEvents.OpenType.COLD, + firePreAndPost = false, + hasRenderEvent = false, + ) + } + + @Config(sdk = [Build.VERSION_CODES.LOLLIPOP]) + @Test + fun `verify cold open trace from background in L`() { + verifyOpen( + fromBackground = true, + openType = OpenEvents.OpenType.COLD, + firePreAndPost = false, + hasRenderEvent = false, + ) + } + + @Config(sdk = [Build.VERSION_CODES.LOLLIPOP]) + @Test + fun `verify hot open trace in L from background`() { + verifyOpen( + fromBackground = true, + openType = OpenEvents.OpenType.HOT, + firePreAndPost = false, + hasRenderEvent = false, + ) + } + + private fun verifyOpen( + fromBackground: Boolean, + openType: OpenEvents.OpenType, + firePreAndPost: Boolean, + hasRenderEvent: Boolean, + ) { + openActivity( + fromBackground = fromBackground, + openType = openType, + firePreAndPost = firePreAndPost, + hasRenderEvent = hasRenderEvent + ).let { timestamps -> + val spanMap = spanSink.completedSpans().associateBy { it.name } + val trace = checkNotNull(spanMap["emb-${ACTIVITY_NAME}-${openType.typeName}-open"]) + + assertEmbraceSpanData( + span = trace.toNewPayload(), + expectedStartTimeMs = timestamps.first, + expectedEndTimeMs = timestamps.second, + expectedParentId = SpanId.getInvalid(), + key = true, + ) + + val events = timestamps.third + if (openType == OpenEvents.OpenType.COLD) { + checkNotNull(events[OpenTraceEmitter.LifecycleEvent.CREATE]).run { + assertEmbraceSpanData( + span = checkNotNull(spanMap["emb-$ACTIVITY_NAME-create"]).toNewPayload(), + expectedStartTimeMs = startMs(), + expectedEndTimeMs = endMs(), + expectedParentId = trace.spanId + ) + } + } else { + assertNull(spanMap["emb-$ACTIVITY_NAME-create"]) + } + + checkNotNull(events[OpenTraceEmitter.LifecycleEvent.START]).run { + assertEmbraceSpanData( + span = checkNotNull(spanMap["emb-$ACTIVITY_NAME-start"]).toNewPayload(), + expectedStartTimeMs = startMs(), + expectedEndTimeMs = endMs(), + expectedParentId = trace.spanId + ) + } + + if (hasRenderEvent) { + checkNotNull(events[OpenTraceEmitter.LifecycleEvent.RESUME]).run { + assertEmbraceSpanData( + span = checkNotNull(spanMap["emb-$ACTIVITY_NAME-resume"]).toNewPayload(), + expectedStartTimeMs = startMs(), + expectedEndTimeMs = endMs(), + expectedParentId = trace.spanId + ) + } + checkNotNull(events[OpenTraceEmitter.LifecycleEvent.RENDER]).run { + assertEmbraceSpanData( + span = checkNotNull(spanMap["emb-$ACTIVITY_NAME-render"]).toNewPayload(), + expectedStartTimeMs = startMs(), + expectedEndTimeMs = endMs(), + expectedParentId = trace.spanId + ) + } + } else { + assertNull(spanMap["emb-$ACTIVITY_NAME-resume"]) + assertNull(spanMap["emb-$ACTIVITY_NAME-render"]) + } + } + } + + @Suppress("CyclomaticComplexMethod", "ComplexMethod") + private fun openActivity( + fromBackground: Boolean, + openType: OpenEvents.OpenType, + firePreAndPost: Boolean, + hasRenderEvent: Boolean + ): Triple> { + val events = mutableMapOf() + val lastActivityExitMs = clock.now() + traceEmitter.resetTrace(LAST_ACTIVITY_INSTANCE, LAST_ACTIVITY, lastActivityExitMs) + clock.tick(100L) + + if (fromBackground) { + traceEmitter.hibernate(LAST_ACTIVITY_INSTANCE, LAST_ACTIVITY, clock.now()) + } + + val createEvents = if (openType == OpenEvents.OpenType.COLD) { + activityCreate(firePreAndPost) + } else { + null + }?.apply { + events[OpenTraceEmitter.LifecycleEvent.CREATE] = this + } + + val startEvents = activityStart(firePreAndPost).apply { + events[OpenTraceEmitter.LifecycleEvent.START] = this + } + + val resumeEvents = activityResume(firePreAndPost).apply { + events[OpenTraceEmitter.LifecycleEvent.RESUME] = this + } + + val renderEvents = if (hasRenderEvent) { + activityRender(firePreAndPost) + } else { + null + }?.apply { + events[OpenTraceEmitter.LifecycleEvent.RENDER] = this + } + + val traceStartMs = if (!fromBackground) { + lastActivityExitMs + } else { + createEvents?.run { + if (firePreAndPost) { + pre + } else { + eventStart + } + } ?: if (firePreAndPost) { + startEvents.pre + } else { + startEvents.eventStart + } + } + + val traceEndMs = renderEvents?.run { + endMs() + } ?: resumeEvents.startMs() + + return Triple(traceStartMs, traceEndMs, events) + } + + private fun activityCreate(firePreAndPost: Boolean = true): LifecycleEvents { + return runLifecycleEvent( + startCallback = traceEmitter::create, + endCallback = traceEmitter::createEnd, + firePreAndPost = firePreAndPost, + ) + } + + private fun activityStart(firePreAndPost: Boolean = true): LifecycleEvents { + return runLifecycleEvent( + startCallback = traceEmitter::start, + endCallback = traceEmitter::startEnd, + firePreAndPost = firePreAndPost, + ) + } + + private fun activityResume(firePreAndPost: Boolean = true): LifecycleEvents { + return runLifecycleEvent( + startCallback = traceEmitter::resume, + endCallback = traceEmitter::resumeEnd, + firePreAndPost = firePreAndPost, + ) + } + + private fun activityRender(firePreAndPost: Boolean = true): LifecycleEvents { + return runLifecycleEvent( + startCallback = traceEmitter::render, + endCallback = traceEmitter::renderEnd, + firePreAndPost = firePreAndPost, + ) + } + + private fun runLifecycleEvent( + startCallback: (instanceId: Int, activityName: String, startMs: Long) -> Unit, + endCallback: (instanceId: Int, startMs: Long) -> Unit, + firePreAndPost: Boolean = true + ): LifecycleEvents { + val events = LifecycleEvents() + if (firePreAndPost) { + events.pre = clock.now() + clock.tick() + } + events.eventStart = clock.now() + startCallback(INSTANCE_1, ACTIVITY_NAME, events.startMs()) + events.eventEnd = clock.tick(100L) + if (firePreAndPost) { + events.post = clock.tick() + } + endCallback(INSTANCE_1, events.endMs()) + return events + } + + private data class LifecycleEvents( + var pre: Long = Long.MAX_VALUE, + var eventStart: Long = Long.MAX_VALUE, + var eventEnd: Long = Long.MIN_VALUE, + var post: Long = Long.MIN_VALUE, + ) + + private fun LifecycleEvents.startMs(): Long = min(pre, eventStart) + + private fun LifecycleEvents.endMs(): Long = max(post, eventEnd) + + companion object { + const val INSTANCE_1 = 1 + const val ACTIVITY_NAME = "com.my.CoolActivity" + const val LAST_ACTIVITY = "com.my.Activity" + const val LAST_ACTIVITY_INSTANCE = 99 + } +}