diff --git a/CHANGELOG.md b/CHANGELOG.md index 64b861a977..9369821951 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ - Attaches spans for Application, ContentProvider, and Activities to app-start timings - Uses Process.startUptimeMillis to calculate app-start timings - To enable this feature set `options.isEnablePerformanceV2 = true` +- Move slow+frozen frame calculation, as well as frame delay inside SentryFrameMetricsCollector ([#3100](https://github.com/getsentry/sentry-java/pull/3100)) ### Fixes diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java index a4e097ec00..ee4dd84374 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java @@ -139,13 +139,17 @@ public AndroidProfiler( frameMetricsCollectorId = frameMetricsCollector.startCollection( new SentryFrameMetricsCollector.FrameMetricsCollectorListener() { - final long nanosInSecond = TimeUnit.SECONDS.toNanos(1); - final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700); float lastRefreshRate = 0; @Override public void onFrameMetricCollected( - final long frameEndNanos, final long durationNanos, float refreshRate) { + final long frameStartNanos, + final long frameEndNanos, + final long durationNanos, + final long delayNanos, + final boolean isSlow, + final boolean isFrozen, + final float refreshRate) { // transactionStartNanos is calculated through SystemClock.elapsedRealtimeNanos(), // but frameEndNanos uses System.nanotime(), so we convert it to get the timestamp // relative to transactionStartNanos @@ -160,22 +164,17 @@ public void onFrameMetricCollected( if (frameTimestampRelativeNanos < 0) { return; } - // Most frames take just a few nanoseconds longer than the optimal calculated - // duration. - // Therefore we subtract one, because otherwise almost all frames would be slow. - boolean isSlow = durationNanos > nanosInSecond / (refreshRate - 1); - float newRefreshRate = (int) (refreshRate * 100) / 100F; - if (durationNanos > frozenFrameThresholdNanos) { + if (isFrozen) { frozenFrameRenderMeasurements.addLast( new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos)); } else if (isSlow) { slowFrameRenderMeasurements.addLast( new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos)); } - if (newRefreshRate != lastRefreshRate) { - lastRefreshRate = newRefreshRate; + if (refreshRate != lastRefreshRate) { + lastRefreshRate = refreshRate; screenFrameRateMeasurements.addLast( - new ProfileMeasurementValue(frameTimestampRelativeNanos, newRefreshRate)); + new ProfileMeasurementValue(frameTimestampRelativeNanos, refreshRate)); } } }); diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollector.java b/sentry-android-core/src/main/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollector.java index 2d600ae65c..062084842c 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollector.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollector.java @@ -25,12 +25,16 @@ import java.util.UUID; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CopyOnWriteArraySet; +import java.util.concurrent.TimeUnit; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; @ApiStatus.Internal public final class SentryFrameMetricsCollector implements Application.ActivityLifecycleCallbacks { + private static final long oneSecondInNanos = TimeUnit.SECONDS.toNanos(1); + private static final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700); + private final @NotNull BuildInfoProvider buildInfoProvider; private final @NotNull Set trackedWindows = new CopyOnWriteArraySet<>(); private final @NotNull ILogger logger; @@ -132,6 +136,7 @@ public SentryFrameMetricsCollector( logger.log( SentryLevel.ERROR, "Unable to get the frame timestamp from the choreographer: ", e); } + frameMetricsAvailableListener = (window, frameMetrics, dropCountSinceLastInvocation) -> { final long now = System.nanoTime(); @@ -140,7 +145,14 @@ public SentryFrameMetricsCollector( ? window.getContext().getDisplay().getRefreshRate() : window.getWindowManager().getDefaultDisplay().getRefreshRate(); + final long expectedFrameDuration = (long) (oneSecondInNanos / refreshRate); + final long cpuDuration = getFrameCpuDuration(frameMetrics); + + // if totalDurationNanos is smaller than expectedFrameTimeNanos, + // it means that the frame was drawn within it's time budget, thus 0 delay + final long delayNanos = Math.max(0, cpuDuration - expectedFrameDuration); + long startTime = getFrameStartTimestamp(frameMetrics); // If we couldn't get the timestamp through reflection, we use current time if (startTime < 0) { @@ -155,8 +167,21 @@ public SentryFrameMetricsCollector( lastFrameStartNanos = startTime; lastFrameEndNanos = startTime + cpuDuration; + // Most frames take just a few nanoseconds longer than the optimal calculated + // duration. + // Therefore we subtract one, because otherwise almost all frames would be slow. + final boolean isSlow = cpuDuration > oneSecondInNanos / (refreshRate - 1); + final boolean isFrozen = isSlow && cpuDuration > frozenFrameThresholdNanos; + for (FrameMetricsCollectorListener l : listenerMap.values()) { - l.onFrameMetricCollected(lastFrameEndNanos, cpuDuration, refreshRate); + l.onFrameMetricCollected( + startTime, + lastFrameEndNanos, + cpuDuration, + delayNanos, + isSlow, + isFrozen, + refreshRate); } }; } @@ -193,6 +218,8 @@ private long getFrameStartTimestamp(final @NotNull FrameMetrics frameMetrics) { */ @RequiresApi(api = Build.VERSION_CODES.N) private long getFrameCpuDuration(final @NotNull FrameMetrics frameMetrics) { + // Inspired by JankStats + // https://cs.android.com/androidx/platform/frameworks/support/+/androidx-main:metrics/metrics-performance/src/main/java/androidx/metrics/performance/JankStatsApi24Impl.kt;l=74-79;drc=1de6215c6bd9e887e3d94556e9ac55cfb7b8c797 return frameMetrics.getMetric(FrameMetrics.UNKNOWN_DELAY_DURATION) + frameMetrics.getMetric(FrameMetrics.INPUT_HANDLING_DURATION) + frameMetrics.getMetric(FrameMetrics.ANIMATION_DURATION) @@ -299,13 +326,26 @@ public interface FrameMetricsCollectorListener { /** * Called when a frame is collected. * + * @param frameStartNanos Start timestamp of a frame in nanoseconds relative to + * System.nanotime(). * @param frameEndNanos End timestamp of a frame in nanoseconds relative to System.nanotime(). * @param durationNanos Duration in nanoseconds of the time spent from the cpu on the main * thread to create the frame. - * @param refreshRate Refresh rate of the screen. + * @param delayNanos the frame delay, in nanoseconds. + * @param isSlow True if the frame is considered slow, rendering taking longer than the + * refresh-rate based budget, false otherwise. + * @param isFrozen True if the frame is considered frozen, rendering taking longer than 700ms, + * false otherwise. + * @param refreshRate the last known refresh rate when the frame was rendered. */ void onFrameMetricCollected( - final long frameEndNanos, final long durationNanos, final float refreshRate); + final long frameStartNanos, + final long frameEndNanos, + final long durationNanos, + final long delayNanos, + final boolean isSlow, + final boolean isFrozen, + final float refreshRate); } @ApiStatus.Internal diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollectorTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollectorTest.kt index 91227253fd..f824d4e67e 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollectorTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollectorTest.kt @@ -25,19 +25,23 @@ import org.mockito.kotlin.whenever import org.robolectric.Shadows import java.lang.ref.WeakReference import java.lang.reflect.Field +import java.util.concurrent.TimeUnit import kotlin.test.BeforeTest import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFailsWith +import kotlin.test.assertFalse import kotlin.test.assertNotNull import kotlin.test.assertNull +import kotlin.test.assertTrue @RunWith(AndroidJUnit4::class) class SentryFrameMetricsCollectorTest { private lateinit var context: Context private val className = "io.sentry.android.core.internal.util.SentryFrameMetricsCollector" - private val ctorTypes = arrayOf(Context::class.java, SentryOptions::class.java, BuildInfoProvider::class.java) + private val ctorTypes = + arrayOf(Context::class.java, SentryOptions::class.java, BuildInfoProvider::class.java) private val fixture = Fixture() private class Fixture { @@ -59,29 +63,38 @@ class SentryFrameMetricsCollectorTest { var addOnFrameMetricsAvailableListenerCounter = 0 var removeOnFrameMetricsAvailableListenerCounter = 0 - val windowFrameMetricsManager = object : SentryFrameMetricsCollector.WindowFrameMetricsManager { - override fun addOnFrameMetricsAvailableListener( - window: Window, - frameMetricsAvailableListener: Window.OnFrameMetricsAvailableListener?, - handler: Handler? - ) { - addOnFrameMetricsAvailableListenerCounter++ + val windowFrameMetricsManager = + object : SentryFrameMetricsCollector.WindowFrameMetricsManager { + override fun addOnFrameMetricsAvailableListener( + window: Window, + frameMetricsAvailableListener: Window.OnFrameMetricsAvailableListener?, + handler: Handler? + ) { + addOnFrameMetricsAvailableListenerCounter++ + } + + override fun removeOnFrameMetricsAvailableListener( + window: Window, + frameMetricsAvailableListener: Window.OnFrameMetricsAvailableListener? + ) { + removeOnFrameMetricsAvailableListenerCounter++ + } } - override fun removeOnFrameMetricsAvailableListener( - window: Window, - frameMetricsAvailableListener: Window.OnFrameMetricsAvailableListener? - ) { - removeOnFrameMetricsAvailableListenerCounter++ - } - } - - fun getSut(context: Context, buildInfoProvider: BuildInfoProvider = buildInfo): SentryFrameMetricsCollector { + fun getSut( + context: Context, + buildInfoProvider: BuildInfoProvider = buildInfo + ): SentryFrameMetricsCollector { whenever(activity.window).thenReturn(window) whenever(activity2.window).thenReturn(window2) addOnFrameMetricsAvailableListenerCounter = 0 removeOnFrameMetricsAvailableListenerCounter = 0 - return SentryFrameMetricsCollector(context, options, buildInfoProvider, windowFrameMetricsManager) + return SentryFrameMetricsCollector( + context, + options, + buildInfoProvider, + windowFrameMetricsManager + ) } } @@ -274,13 +287,17 @@ class SentryFrameMetricsCollectorTest { val collector = fixture.getSut(context) // Execute all posted tasks Shadows.shadowOf(Looper.getMainLooper()).idle() - val listener = collector.getProperty("frameMetricsAvailableListener") + val listener = + collector.getProperty("frameMetricsAvailableListener") val choreographer = collector.getProperty("choreographer") choreographer.injectForField("mLastFrameTimeNanos", 100) val frameMetrics = createMockFrameMetrics() var timesCalled = 0 - collector.startCollection { frameEndNanos, durationNanos, refreshRate -> + collector.startCollection { frameStartNanos, frameEndNanos, + durationNanos, delayNanos, + isSlow, isFrozen, + refreshRate -> // The frame end is 100 (Choreographer.mLastFrameTimeNanos) plus frame duration assertEquals(100 + durationNanos, frameEndNanos) timesCalled++ @@ -296,13 +313,16 @@ class SentryFrameMetricsCollectorTest { whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O) } val collector = fixture.getSut(context, buildInfo) - val listener = collector.getProperty("frameMetricsAvailableListener") - // FrameMetrics with cpu time of 21 nanoseconds and INTENDED_VSYNC_TIMESTAMP of 50 nanoseconds + val listener = + collector.getProperty("frameMetricsAvailableListener") val frameMetrics = createMockFrameMetrics() // We don't inject the choreographer field var timesCalled = 0 - collector.startCollection { frameEndNanos, durationNanos, refreshRate -> + collector.startCollection { frameStartNanos, frameEndNanos, + durationNanos, delayNanos, + isSlow, isFrozen, + refreshRate -> assertEquals(50 + durationNanos, frameEndNanos) timesCalled++ } @@ -317,12 +337,16 @@ class SentryFrameMetricsCollectorTest { whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O) } val collector = fixture.getSut(context, buildInfo) - val listener = collector.getProperty("frameMetricsAvailableListener") + val listener = + collector.getProperty("frameMetricsAvailableListener") // FrameMetrics with cpu time of 21 nanoseconds and TOTAL_DURATION of 60 nanoseconds val frameMetrics = createMockFrameMetrics() var timesCalled = 0 - collector.startCollection { frameEndNanos, durationNanos, refreshRate -> + collector.startCollection { frameStartNanos, frameEndNanos, + durationNanos, delayNanos, + isSlow, isFrozen, + refreshRate -> assertEquals(21, durationNanos) timesCalled++ } @@ -337,12 +361,16 @@ class SentryFrameMetricsCollectorTest { whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O) } val collector = fixture.getSut(context, buildInfo) - val listener = collector.getProperty("frameMetricsAvailableListener") + val listener = + collector.getProperty("frameMetricsAvailableListener") val frameMetrics = createMockFrameMetrics() whenever(frameMetrics.getMetric(FrameMetrics.INTENDED_VSYNC_TIMESTAMP)).thenReturn(50) var previousEnd = 0L var timesCalled = 0 - collector.startCollection { frameEndNanos, durationNanos, refreshRate -> + collector.startCollection { frameStartNanos, frameEndNanos, + durationNanos, delayNanos, + isSlow, isFrozen, + refreshRate -> // The second time the listener is called, the frame start is shifted to be equal to the previous frame end if (timesCalled > 0) { assertEquals(previousEnd + durationNanos, frameEndNanos) @@ -356,25 +384,171 @@ class SentryFrameMetricsCollectorTest { assertEquals(2, timesCalled) } - private fun createMockWindow(): Window { + @Test + fun `collector properly reports slow and frozen flags`() { + val buildInfo = mock { + whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O) + } + val collector = fixture.getSut(context, buildInfo) + val listener = + collector.getProperty("frameMetricsAvailableListener") + + var timesCalled = 0 + var lastIsSlow = false + var lastIsFrozen = false + + // when a frame takes less than 16ms, it's not considered slow or frozen + collector.startCollection { _, _, + _, _, + isSlow, isFrozen, + _ -> + + lastIsSlow = isSlow + lastIsFrozen = isFrozen + timesCalled++ + } + listener.onFrameMetricsAvailable(createMockWindow(), createMockFrameMetrics(), 0) + assertFalse(lastIsSlow) + assertFalse(lastIsFrozen) + + // when a frame takes more than 16ms, it's considered slow but not frozen + listener.onFrameMetricsAvailable( + createMockWindow(), + createMockFrameMetrics( + extraCpuDurationNanos = TimeUnit.MILLISECONDS.toNanos(100) + ), + 0 + ) + assertTrue(lastIsSlow) + assertFalse(lastIsFrozen) + + // when a frame takes more than 700ms, it's considered slow and frozen + listener.onFrameMetricsAvailable( + createMockWindow(), + createMockFrameMetrics( + extraCpuDurationNanos = TimeUnit.MILLISECONDS.toNanos(1000) + ), + 0 + ) + assertTrue(lastIsSlow) + assertTrue(lastIsFrozen) + + // Assert the callbacks were called + assertEquals(3, timesCalled) + } + + @Test + fun `collector properly reports frame delay`() { + val buildInfo = mock { + whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O) + } + val collector = fixture.getSut(context, buildInfo) + val listener = + collector.getProperty("frameMetricsAvailableListener") + + var lastDelay = 0L + + // when a frame takes less than 16ms, it's not considered slow or frozen + collector.startCollection { _, _, + _, delayNanos, + _, _, + _ -> + lastDelay = delayNanos + } + // at 60hz, when the total duration is 10ms, the delay is 0 + listener.onFrameMetricsAvailable( + createMockWindow(), + createMockFrameMetrics( + unknownDelayNanos = 0, + animationNanos = 0, + inputHandlingNanos = 0, + layoutMeasureNanos = 0, + drawNanos = 0, + syncNanos = 0, + extraCpuDurationNanos = TimeUnit.MILLISECONDS.toNanos(16) + ), + 0 + ) + assertEquals(0, lastDelay) + + // at 60hz, when the total duration is 20ms, the delay is considered ~4ms + listener.onFrameMetricsAvailable( + createMockWindow(), + createMockFrameMetrics( + unknownDelayNanos = 0, + animationNanos = 0, + inputHandlingNanos = 0, + layoutMeasureNanos = 0, + drawNanos = 0, + syncNanos = 0, + extraCpuDurationNanos = TimeUnit.MILLISECONDS.toNanos(20) + ), + 0 + ) + assertEquals( + // 20ms - 1/60 (~16.6ms) = 4ms + TimeUnit.MILLISECONDS.toNanos(20) - (TimeUnit.SECONDS.toNanos(1) / 60.0f).toLong(), + lastDelay + ) + + // at 120hz, when the total duration is 20ms, the delay is considered ~8ms + listener.onFrameMetricsAvailable( + createMockWindow(120.0f), + createMockFrameMetrics( + unknownDelayNanos = 0, + animationNanos = 0, + inputHandlingNanos = 0, + layoutMeasureNanos = 0, + drawNanos = 0, + syncNanos = 0, + extraCpuDurationNanos = TimeUnit.MILLISECONDS.toNanos(20) + ), + 0 + ) + assertEquals( + // 20ms - 1/120 (~8.33ms) = 8ms + TimeUnit.MILLISECONDS.toNanos(20) - (TimeUnit.SECONDS.toNanos(1) / 120.0f).toLong(), + lastDelay + ) + } + + private fun createMockWindow(refreshRate: Float = 60F): Window { val mockWindow = mock() val mockDisplay = mock() val mockWindowManager = mock() whenever(mockWindow.windowManager).thenReturn(mockWindowManager) whenever(mockWindowManager.defaultDisplay).thenReturn(mockDisplay) - whenever(mockDisplay.refreshRate).thenReturn(60F) + whenever(mockDisplay.refreshRate).thenReturn(refreshRate) return mockWindow } - private fun createMockFrameMetrics(): FrameMetrics { + /** + * FrameMetrics with default cpu time of 21 nanoseconds and INTENDED_VSYNC_TIMESTAMP of 50 nanoseconds + */ + private fun createMockFrameMetrics( + unknownDelayNanos: Long = 1, + inputHandlingNanos: Long = 2, + animationNanos: Long = 3, + layoutMeasureNanos: Long = 4, + drawNanos: Long = 5, + syncNanos: Long = 6, + extraCpuDurationNanos: Long = 0, + totalDurationNanos: Long = 60 + ): FrameMetrics { val frameMetrics = mock() - whenever(frameMetrics.getMetric(FrameMetrics.UNKNOWN_DELAY_DURATION)).thenReturn(1) - whenever(frameMetrics.getMetric(FrameMetrics.INPUT_HANDLING_DURATION)).thenReturn(2) - whenever(frameMetrics.getMetric(FrameMetrics.ANIMATION_DURATION)).thenReturn(3) - whenever(frameMetrics.getMetric(FrameMetrics.LAYOUT_MEASURE_DURATION)).thenReturn(4) - whenever(frameMetrics.getMetric(FrameMetrics.DRAW_DURATION)).thenReturn(5) - whenever(frameMetrics.getMetric(FrameMetrics.SYNC_DURATION)).thenReturn(6) - whenever(frameMetrics.getMetric(FrameMetrics.TOTAL_DURATION)).thenReturn(60) + whenever(frameMetrics.getMetric(FrameMetrics.UNKNOWN_DELAY_DURATION)).thenReturn( + unknownDelayNanos + extraCpuDurationNanos + ) + whenever(frameMetrics.getMetric(FrameMetrics.INPUT_HANDLING_DURATION)).thenReturn( + inputHandlingNanos + ) + whenever(frameMetrics.getMetric(FrameMetrics.ANIMATION_DURATION)).thenReturn(animationNanos) + whenever(frameMetrics.getMetric(FrameMetrics.LAYOUT_MEASURE_DURATION)).thenReturn( + layoutMeasureNanos + ) + whenever(frameMetrics.getMetric(FrameMetrics.DRAW_DURATION)).thenReturn(drawNanos) + whenever(frameMetrics.getMetric(FrameMetrics.SYNC_DURATION)).thenReturn(syncNanos) + whenever(frameMetrics.getMetric(FrameMetrics.TOTAL_DURATION)).thenReturn(totalDurationNanos) whenever(frameMetrics.getMetric(FrameMetrics.INTENDED_VSYNC_TIMESTAMP)).thenReturn(50) return frameMetrics }