diff --git a/CHANGELOG.md b/CHANGELOG.md index 402e177555..d54fafd87a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,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-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..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 @@ -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 are 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..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 @@ -4,6 +4,8 @@ import io.sentry.DateUtils; 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; @@ -21,6 +23,7 @@ public class TimeSpan implements Comparable { private @Nullable String description; + private long startSystemNanos; private long startUnixTimeMs; private long startUptimeMs; private long stopUptimeMs; @@ -29,6 +32,7 @@ public class TimeSpan implements Comparable { public void start() { startUptimeMs = SystemClock.uptimeMillis(); startUnixTimeMs = System.currentTimeMillis(); + startSystemNanos = System.nanoTime(); } /** @@ -40,6 +44,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 */ @@ -90,7 +95,8 @@ public long getStartTimestampMs() { */ public @Nullable SentryDate getStartTimestamp() { if (hasStarted()) { - return new SentryLongDate(DateUtils.millisToNanos(getStartTimestampMs())); + return new SentryNanotimeDate( + DateUtils.nanosToDate(DateUtils.millisToNanos(getStartTimestampMs())), startSystemNanos); } return null; } @@ -162,6 +168,7 @@ public void reset() { startUptimeMs = 0; stopUptimeMs = 0; startUnixTimeMs = 0; + startSystemNanos = 0; } @Override 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..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 @@ -2,13 +2,23 @@ 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.Assume 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 +59,84 @@ 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) + // 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.") + } + 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) + // 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.") + } + 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-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" 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