From 3e397d09a97f85aede4f671376b686bb42ef02c7 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 23 Apr 2024 13:27:21 +0200 Subject: [PATCH 1/6] 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 1121a6bfe7..750caa0e12 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 b5f0332c67..c0ada9843b 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 5397790588..e8ef2eb238 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 0d34a8fb07..5ec5622ac2 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 7f2d771b7d..5be4811c19 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 bc3b5eb531..f5bbc5d156 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 f92e90799c..c883937383 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/6] 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 34b429a9c4..a99f12fdf7 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 5be4811c19..d5dd0fd80e 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.") } From 1bfb66d433b9357b875b80442df31da9f073d414 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 23 Apr 2024 15:56:46 +0200 Subject: [PATCH 3/6] set TimeSpan nanotime in TimeSpan.start --- .../java/io/sentry/android/core/performance/TimeSpan.java | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) 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 e8ef2eb238..f3ac5873a3 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 @@ -10,6 +10,8 @@ import org.jetbrains.annotations.Nullable; import org.jetbrains.annotations.TestOnly; +import java.util.concurrent.TimeUnit; + /** * A measurement for time critical components on a macro (ms) level. Based on {@link * SystemClock#uptimeMillis()} to ensure linear time progression (as opposed to a syncable clock). @@ -22,6 +24,7 @@ public class TimeSpan implements Comparable { private @Nullable String description; + private long startSystemNanos; private long startUnixTimeMs; private long startUptimeMs; private long stopUptimeMs; @@ -30,6 +33,7 @@ public class TimeSpan implements Comparable { public void start() { startUptimeMs = SystemClock.uptimeMillis(); startUnixTimeMs = System.currentTimeMillis(); + startSystemNanos = System.nanoTime(); } /** @@ -41,6 +45,7 @@ public void setStartedAt(final long uptimeMs) { final long shiftMs = SystemClock.uptimeMillis() - startUptimeMs; startUnixTimeMs = System.currentTimeMillis() - shiftMs; + startSystemNanos = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(shiftMs); } /** Stops the time span */ @@ -92,7 +97,7 @@ public long getStartTimestampMs() { public @Nullable SentryDate getStartTimestamp() { if (hasStarted()) { return new SentryNanotimeDate( - DateUtils.nanosToDate(DateUtils.millisToNanos(getStartTimestampMs())), System.nanoTime()); + DateUtils.nanosToDate(DateUtils.millisToNanos(getStartTimestampMs())), startSystemNanos); } return null; } @@ -164,6 +169,7 @@ public void reset() { startUptimeMs = 0; stopUptimeMs = 0; startUnixTimeMs = 0; + startSystemNanos = 0; } @Override From 0172c88453c13e17862527e19988db2056527035 Mon Sep 17 00:00:00 2001 From: Sentry Github Bot Date: Tue, 23 Apr 2024 13:59:00 +0000 Subject: [PATCH 4/6] Format code --- .../main/java/io/sentry/android/core/performance/TimeSpan.java | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) 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 f3ac5873a3..ff5cfe8649 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 @@ -5,13 +5,12 @@ import io.sentry.SentryDate; import io.sentry.SentryLongDate; import io.sentry.SentryNanotimeDate; +import java.util.concurrent.TimeUnit; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; import org.jetbrains.annotations.TestOnly; -import java.util.concurrent.TimeUnit; - /** * A measurement for time critical components on a macro (ms) level. Based on {@link * SystemClock#uptimeMillis()} to ensure linear time progression (as opposed to a syncable clock). From f55e3a64597a68450dfc6b3a445850668ba692fd Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 23 Apr 2024 16:27:24 +0200 Subject: [PATCH 5/6] run ci again --- .../java/io/sentry/android/core/SpanFrameMetricsCollector.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 c0ada9843b..e32351936b 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 @@ -144,7 +144,7 @@ private void captureFrameMetrics(@NotNull final ISpan span) { 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) + // same kind of dates (both are SentryNanotimeDate or both SentryLongDate) final long spanEndNanos = realNanos(spanFinishDate); final @NotNull SentryFrameMetrics frameMetrics = new SentryFrameMetrics(); From 121a2f2a4f62f059902ada77750e16796fe2f185 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 23 Apr 2024 18:05:16 +0200 Subject: [PATCH 6/6] reverted ActivityLifecycleIntegration overwrite ttfd measurement --- .../io/sentry/android/core/ActivityLifecycleIntegration.java | 2 +- .../androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt | 2 +- 2 files changed, 2 insertions(+), 2 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 750caa0e12..1121a6bfe7 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 - ttfdSpan.setMeasurement( + ttidSpan.setMeasurement( MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND); } finishSpan(ttidSpan, endDate); diff --git a/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt b/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt index 6825933ea3..ebf729f6b6 100644 --- a/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt +++ b/sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt @@ -157,7 +157,7 @@ class EnvelopeTests : BaseUiTest() { // Timestamps of measurements should differ at least 10 milliseconds from each other (1 until values.size).forEach { i -> assertTrue( - values[i].relativeStartNs.toLong() > values[i - 1].relativeStartNs.toLong() + TimeUnit.MILLISECONDS.toNanos( + values[i].relativeStartNs.toLong() >= values[i - 1].relativeStartNs.toLong() + TimeUnit.MILLISECONDS.toNanos( 10 ), "Measurement value timestamp for '$name' does not differ at least 10ms"