From 3e397d09a97f85aede4f671376b686bb42ef02c7 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 23 Apr 2024 13:27:21 +0200 Subject: [PATCH 1/2] performance collectors are called independently from profiling (now transactions get frames measurements) TimeSpan.getStartTimestamp is now a SentryNanotimeDate, to fix FrameMetricsCollector on app start transactions --- .../core/ActivityLifecycleIntegration.java | 2 +- .../core/SpanFrameMetricsCollector.java | 9 +- .../android/core/performance/TimeSpan.java | 4 +- .../core/SpanFrameMetricsCollectorTest.kt | 4 +- .../uitest/android/AutomaticSpansTest.kt | 85 +++++++++++++++++++ .../src/main/java/io/sentry/SentryTracer.java | 6 +- .../test/java/io/sentry/SentryTracerTest.kt | 4 +- 7 files changed, 102 insertions(+), 12 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java index 1121a6bfe75..750caa0e126 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java @@ -560,7 +560,7 @@ private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable I if (ttfdSpan != null && ttfdSpan.isFinished()) { ttfdSpan.updateEndDate(endDate); // If the ttfd span was finished before the first frame we adjust the measurement, too - ttidSpan.setMeasurement( + ttfdSpan.setMeasurement( MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND); } finishSpan(ttidSpan, endDate); diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java index b5f0332c674..c0ada9843b5 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java @@ -7,6 +7,7 @@ import io.sentry.NoOpTransaction; import io.sentry.SentryDate; import io.sentry.SentryNanotimeDate; +import io.sentry.SentryTracer; import io.sentry.SpanDataConvention; import io.sentry.android.core.internal.util.SentryFrameMetricsCollector; import io.sentry.protocol.MeasurementValue; @@ -135,11 +136,15 @@ private void captureFrameMetrics(@NotNull final ISpan span) { return; } - // ignore spans with no finish date - final @Nullable SentryDate spanFinishDate = span.getFinishDate(); + // Ignore spans with no finish date, but SentryTracer is not finished when executing this + // callback, yet, so in that case we use the current timestamp. + final @Nullable SentryDate spanFinishDate = + span instanceof SentryTracer ? new SentryNanotimeDate() : span.getFinishDate(); if (spanFinishDate == null) { return; } + // Note: The comparison between two values obtained by realNanos() works only if both are the + // same kind of dates (both SentryNanotimeDate or both SentryLongDate) final long spanEndNanos = realNanos(spanFinishDate); final @NotNull SentryFrameMetrics frameMetrics = new SentryFrameMetrics(); diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java b/sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java index 53977905883..e8ef2eb2384 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java @@ -4,6 +4,7 @@ import io.sentry.DateUtils; import io.sentry.SentryDate; import io.sentry.SentryLongDate; +import io.sentry.SentryNanotimeDate; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; @@ -90,7 +91,8 @@ public long getStartTimestampMs() { */ public @Nullable SentryDate getStartTimestamp() { if (hasStarted()) { - return new SentryLongDate(DateUtils.millisToNanos(getStartTimestampMs())); + return new SentryNanotimeDate( + DateUtils.nanosToDate(DateUtils.millisToNanos(getStartTimestampMs())), System.nanoTime()); } return null; } diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt index 0d34a8fb073..5ec5622ac2e 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt @@ -40,9 +40,7 @@ class SpanFrameMetricsCollectorTest { options.frameMetricsCollector = frameMetricsCollector options.isEnableFramesTracking = enabled options.isEnablePerformanceV2 = enabled - options.setDateProvider { - SentryLongDate(timeNanos) - } + options.dateProvider = SentryAndroidDateProvider() return SpanFrameMetricsCollector(options, frameMetricsCollector) } diff --git a/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt b/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt index 7f2d771b7db..5be4811c196 100644 --- a/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt +++ b/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt @@ -2,13 +2,22 @@ package io.sentry.uitest.android import androidx.lifecycle.Lifecycle import androidx.test.core.app.launchActivity +import androidx.test.espresso.Espresso +import androidx.test.espresso.IdlingRegistry +import androidx.test.espresso.action.ViewActions +import androidx.test.espresso.matcher.ViewMatchers import androidx.test.ext.junit.runners.AndroidJUnit4 import io.sentry.Sentry import io.sentry.SentryLevel +import io.sentry.android.core.AndroidLogger import io.sentry.android.core.SentryAndroidOptions +import io.sentry.assertEnvelopeTransaction +import io.sentry.protocol.MeasurementValue import io.sentry.protocol.SentryTransaction import org.junit.runner.RunWith import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertNotEquals import kotlin.test.assertTrue @RunWith(AndroidJUnit4::class) @@ -49,4 +58,80 @@ class AutomaticSpansTest : BaseUiTest() { } } } + + @Test + fun checkAppStartFramesMeasurements() { + initSentry(true) { options: SentryAndroidOptions -> + options.tracesSampleRate = 1.0 + options.isEnableTimeToFullDisplayTracing = true + options.isEnablePerformanceV2 = false + } + + IdlingRegistry.getInstance().register(ProfilingSampleActivity.scrollingIdlingResource) + val sampleScenario = launchActivity() + swipeList(3) + Sentry.reportFullyDisplayed() + sampleScenario.moveToState(Lifecycle.State.DESTROYED) + IdlingRegistry.getInstance().unregister(ProfilingSampleActivity.scrollingIdlingResource) + relayIdlingResource.increment() + + relay.assert { + findEnvelope { + assertEnvelopeTransaction(it.items.toList(), AndroidLogger()).transaction == "ProfilingSampleActivity" + }.assert { + val transactionItem: SentryTransaction = it.assertTransaction() + it.assertNoOtherItems() + val measurements = transactionItem.measurements + val frozenFrames = measurements[MeasurementValue.KEY_FRAMES_FROZEN]?.value?.toInt() ?: 0 + val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0 + val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0 + assertEquals("ProfilingSampleActivity", transactionItem.transaction) + assertNotEquals(totalFrames, 0) + assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.") + } + assertNoOtherEnvelopes() + } + } + + @Test + fun checkAppStartFramesMeasurementsPerfV2() { + initSentry(true) { options: SentryAndroidOptions -> + options.tracesSampleRate = 1.0 + options.isEnableTimeToFullDisplayTracing = true + options.isEnablePerformanceV2 = true + } + + IdlingRegistry.getInstance().register(ProfilingSampleActivity.scrollingIdlingResource) + val sampleScenario = launchActivity() + swipeList(3) + Sentry.reportFullyDisplayed() + sampleScenario.moveToState(Lifecycle.State.DESTROYED) + IdlingRegistry.getInstance().unregister(ProfilingSampleActivity.scrollingIdlingResource) + relayIdlingResource.increment() + + relay.assert { + findEnvelope { + assertEnvelopeTransaction(it.items.toList(), AndroidLogger()).transaction == "ProfilingSampleActivity" + }.assert { + val transactionItem: SentryTransaction = it.assertTransaction() + it.assertNoOtherItems() + val measurements = transactionItem.measurements + val frozenFrames = measurements[MeasurementValue.KEY_FRAMES_FROZEN]?.value?.toInt() ?: 0 + val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0 + val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0 + assertEquals("ProfilingSampleActivity", transactionItem.transaction) + assertNotEquals(totalFrames, 0) + assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.") + } + assertNoOtherEnvelopes() + } + } + + private fun swipeList(times: Int) { + repeat(times) { + Thread.sleep(100) + Espresso.onView(ViewMatchers.withId(R.id.profiling_sample_list)).perform(ViewActions.swipeUp()) + Espresso.onIdle() + } + } } diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index bc3b5eb531f..f5bbc5d156e 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -87,9 +87,9 @@ public SentryTracer( this.baggage = new Baggage(hub.getOptions().getLogger()); } - // We are currently sending the performance data only in profiles, so there's no point in - // collecting them if a profile is not sampled - if (transactionPerformanceCollector != null && Boolean.TRUE.equals(isProfileSampled())) { + // We are currently sending the performance data only in profiles, but we are always sending + // performance measurements. + if (transactionPerformanceCollector != null) { transactionPerformanceCollector.start(this); } diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index f92e90799cb..c8839373836 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -1005,9 +1005,9 @@ class SentryTracerTest { } @Test - fun `when transaction is created, but not profiled, transactionPerformanceCollector is not started`() { + fun `when transaction is created, but not profiled, transactionPerformanceCollector is started anyway`() { val transaction = fixture.getSut() - verify(fixture.transactionPerformanceCollector, never()).start(anyOrNull()) + verify(fixture.transactionPerformanceCollector).start(anyOrNull()) } @Test From 395e5d9a29cc42f49d48a7e2a73a1590fb769707 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 23 Apr 2024 13:44:07 +0200 Subject: [PATCH 2/2] updated changelog --- CHANGELOG.md | 1 + .../java/io/sentry/uitest/android/AutomaticSpansTest.kt | 5 +++++ 2 files changed, 6 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 34b429a9c45..a99f12fdf7e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ### Fixes +- Fix Frame measurements in app start transactions ([#3382](https://github.com/getsentry/sentry-java/pull/3382)) - Fix timing metric value different from span duration ([#3368](https://github.com/getsentry/sentry-java/pull/3368)) ## 7.8.0 diff --git a/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt b/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt index 5be4811c196..d5dd0fd80ee 100644 --- a/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt +++ b/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt @@ -14,6 +14,7 @@ import io.sentry.android.core.SentryAndroidOptions import io.sentry.assertEnvelopeTransaction import io.sentry.protocol.MeasurementValue import io.sentry.protocol.SentryTransaction +import org.junit.Assume import org.junit.runner.RunWith import kotlin.test.Test import kotlin.test.assertEquals @@ -86,6 +87,8 @@ class AutomaticSpansTest : BaseUiTest() { val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0 val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0 assertEquals("ProfilingSampleActivity", transactionItem.transaction) + // AGP matrix tests have no frames + Assume.assumeTrue(totalFrames > 0) assertNotEquals(totalFrames, 0) assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.") } @@ -120,6 +123,8 @@ class AutomaticSpansTest : BaseUiTest() { val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0 val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0 assertEquals("ProfilingSampleActivity", transactionItem.transaction) + // AGP matrix tests have no frames + Assume.assumeTrue(totalFrames > 0) assertNotEquals(totalFrames, 0) assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.") }