From a537f8a45828b751272940034c4a64ee5f8fd278 Mon Sep 17 00:00:00 2001 From: Markus Hintersteiner Date: Mon, 12 Feb 2024 13:02:47 +0100 Subject: [PATCH] Report process init time for app start (#3159) * Report process init time for app start * Rename op to process.load * Add Changelog * Ensure process init is only attached if it happened in the reasonable past --- CHANGELOG.md | 1 + .../api/sentry-android-core.api | 2 + .../PerformanceAndroidEventProcessor.java | 29 +++++++++-- .../core/performance/AppStartMetrics.java | 12 +++++ .../PerformanceAndroidEventProcessorTest.kt | 49 ++++++++++++++++++- .../core/performance/AppStartMetricsTest.kt | 6 +++ 6 files changed, 94 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 83d4886470..91fd51e42b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ ### Features - Add new threshold parameters to monitor config ([#3181](https://github.com/getsentry/sentry-java/pull/3181)) +- Report process init time as a span for app start performance ([#3159](https://github.com/getsentry/sentry-java/pull/3159)) ## 7.3.0 diff --git a/sentry-android-core/api/sentry-android-core.api b/sentry-android-core/api/sentry-android-core.api index 51eb48f1b2..4a62f5009d 100644 --- a/sentry-android-core/api/sentry-android-core.api +++ b/sentry-android-core/api/sentry-android-core.api @@ -434,6 +434,7 @@ public class io/sentry/android/core/performance/AppStartMetrics { public fun getAppStartTimeSpanWithFallback (Lio/sentry/android/core/SentryAndroidOptions;)Lio/sentry/android/core/performance/TimeSpan; public fun getAppStartType ()Lio/sentry/android/core/performance/AppStartMetrics$AppStartType; public fun getApplicationOnCreateTimeSpan ()Lio/sentry/android/core/performance/TimeSpan; + public fun getClassLoadedUptimeMs ()J public fun getContentProviderOnCreateTimeSpans ()Ljava/util/List; public static fun getInstance ()Lio/sentry/android/core/performance/AppStartMetrics; public fun getSdkInitTimeSpan ()Lio/sentry/android/core/performance/TimeSpan; @@ -445,6 +446,7 @@ public class io/sentry/android/core/performance/AppStartMetrics { public fun setAppStartProfiler (Lio/sentry/ITransactionProfiler;)V public fun setAppStartSamplingDecision (Lio/sentry/TracesSamplingDecision;)V public fun setAppStartType (Lio/sentry/android/core/performance/AppStartMetrics$AppStartType;)V + public fun setClassLoadedUptimeMs (J)V } public final class io/sentry/android/core/performance/AppStartMetrics$AppStartType : java/lang/Enum { diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java b/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java index ec7e3b74d9..12419b4c90 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java @@ -33,6 +33,8 @@ final class PerformanceAndroidEventProcessor implements EventProcessor { private static final String APP_METRICS_CONTENT_PROVIDER_OP = "contentprovider.load"; private static final String APP_METRICS_ACTIVITIES_OP = "activity.load"; private static final String APP_METRICS_APPLICATION_OP = "application.load"; + private static final String APP_METRICS_PROCESS_INIT_OP = "process.load"; + private static final long MAX_PROCESS_INIT_APP_START_DIFF_MS = 10000; private boolean sentStartMeasurement = false; @@ -77,13 +79,13 @@ public SentryEvent process(@NotNull SentryEvent event, @NotNull Hint hint) { if (!sentStartMeasurement && hasAppStartSpan(transaction)) { final @NotNull TimeSpan appStartTimeSpan = AppStartMetrics.getInstance().getAppStartTimeSpanWithFallback(options); - final long appStartUpInterval = appStartTimeSpan.getDurationMs(); + final long appStartUpDurationMs = appStartTimeSpan.getDurationMs(); - // if appStartUpInterval is 0, metrics are not ready to be sent - if (appStartUpInterval != 0) { + // if appStartUpDurationMs is 0, metrics are not ready to be sent + if (appStartUpDurationMs != 0) { final MeasurementValue value = new MeasurementValue( - (float) appStartUpInterval, MeasurementUnit.Duration.MILLISECOND.apiName()); + (float) appStartUpDurationMs, MeasurementUnit.Duration.MILLISECOND.apiName()); final String appStartKey = AppStartMetrics.getInstance().getAppStartType() == AppStartMetrics.AppStartType.COLD @@ -155,6 +157,25 @@ private void attachColdAppStartSpans( } } + // Process init + final long classInitUptimeMs = appStartMetrics.getClassLoadedUptimeMs(); + final @NotNull TimeSpan appStartTimeSpan = appStartMetrics.getAppStartTimeSpan(); + if (appStartTimeSpan.hasStarted() + && Math.abs(classInitUptimeMs - appStartTimeSpan.getStartUptimeMs()) + <= MAX_PROCESS_INIT_APP_START_DIFF_MS) { + final @NotNull TimeSpan processInitTimeSpan = new TimeSpan(); + processInitTimeSpan.setStartedAt(appStartTimeSpan.getStartUptimeMs()); + processInitTimeSpan.setStartUnixTimeMs(appStartTimeSpan.getStartTimestampMs()); + + processInitTimeSpan.setStoppedAt(classInitUptimeMs); + processInitTimeSpan.setDescription("Process Initialization"); + + txn.getSpans() + .add( + timeSpanToSentrySpan( + processInitTimeSpan, parentSpanId, traceId, APP_METRICS_PROCESS_INIT_OP)); + } + // Content Providers final @NotNull List contentProviderOnCreates = appStartMetrics.getContentProviderOnCreateTimeSpans(); diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/performance/AppStartMetrics.java b/sentry-android-core/src/main/java/io/sentry/android/core/performance/AppStartMetrics.java index 06bd04b3db..5c29e95b63 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/performance/AppStartMetrics.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/performance/AppStartMetrics.java @@ -31,6 +31,8 @@ public enum AppStartType { WARM } + private static long CLASS_LOADED_UPTIME_MS = SystemClock.uptimeMillis(); + private static volatile @Nullable AppStartMetrics instance; private @NotNull AppStartType appStartType = AppStartType.UNKNOWN; @@ -121,6 +123,10 @@ public void addActivityLifecycleTimeSpans(final @NotNull ActivityLifecycleTimeSp activityLifecycles.add(timeSpan); } + public long getClassLoadedUptimeMs() { + return CLASS_LOADED_UPTIME_MS; + } + /** * @return the app start time span if it was started and perf-2 is enabled, falls back to the sdk * init time span otherwise @@ -171,6 +177,12 @@ public void setAppStartSamplingDecision( return appStartSamplingDecision; } + @TestOnly + @ApiStatus.Internal + public void setClassLoadedUptimeMs(final long classLoadedUptimeMs) { + CLASS_LOADED_UPTIME_MS = classLoadedUptimeMs; + } + /** * Called by instrumentation * diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt index 1d98aae539..fac32d4e7d 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt @@ -246,6 +246,13 @@ class PerformanceAndroidEventProcessorTest { // then the app start metrics should be attached tr = sut.process(tr, Hint()) + assertTrue( + tr.spans.any { + "process.load" == it.op && + appStartSpan.spanId == it.parentSpanId + } + ) + assertTrue( tr.spans.any { "contentprovider.load" == it.op && @@ -300,7 +307,7 @@ class PerformanceAndroidEventProcessorTest { @Test fun `does not add app start metrics more than once`() { - // given some WARM app start metrics + // given some cold app start metrics val appStartMetrics = AppStartMetrics.getInstance() appStartMetrics.appStartType = AppStartType.COLD appStartMetrics.appStartTimeSpan.setStartedAt(123) @@ -351,6 +358,46 @@ class PerformanceAndroidEventProcessorTest { ) } + @Test + fun `does not add process init span if it happened too early`() { + // given some cold app start metrics + // where class loaded happened way before app start + val appStartMetrics = AppStartMetrics.getInstance() + appStartMetrics.appStartType = AppStartType.COLD + appStartMetrics.appStartTimeSpan.setStartedAt(11001) + appStartMetrics.appStartTimeSpan.setStoppedAt(12000) + appStartMetrics.classLoadedUptimeMs = 1000 + + val sut = fixture.getSut(enablePerformanceV2 = true) + val context = TransactionContext("Activity", UI_LOAD_OP) + val tracer = SentryTracer(context, fixture.hub) + var tr = SentryTransaction(tracer) + val appStartSpan = SentrySpan( + 0.0, + 1.0, + tr.contexts.trace!!.traceId, + SpanId(), + null, + APP_START_COLD, + "App Start", + SpanStatus.OK, + null, + emptyMap(), + null + ) + tr.spans.add(appStartSpan) + + // when the processor attaches the app start spans + tr = sut.process(tr, Hint()) + + // process load should not be included + assertFalse( + tr.spans.any { + "process.load" == it.op + } + ) + } + private fun setAppStart(options: SentryAndroidOptions, coldStart: Boolean = true) { AppStartMetrics.getInstance().apply { appStartType = when (coldStart) { diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/performance/AppStartMetricsTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/performance/AppStartMetricsTest.kt index 1f41f4cea8..0885024b00 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/performance/AppStartMetricsTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/performance/AppStartMetricsTest.kt @@ -12,6 +12,7 @@ import org.mockito.kotlin.mock import org.robolectric.annotation.Config import kotlin.test.Test import kotlin.test.assertEquals +import kotlin.test.assertNotEquals import kotlin.test.assertNull import kotlin.test.assertSame import kotlin.test.assertTrue @@ -100,4 +101,9 @@ class AppStartMetricsTest { val sdkInitSpan = AppStartMetrics.getInstance().sdkInitTimeSpan assertSame(sdkInitSpan, timeSpan) } + + @Test + fun `class load time is set`() { + assertNotEquals(0, AppStartMetrics.getInstance().classLoadedUptimeMs) + } }