Skip to content

Commit faad870

Browse files
markushimarkushi
authored
Merge 281eaa6 into 7eccfdb 
2 parents 7eccfdb + 281eaa6 commit faad870

File tree

3 files changed

+187
-25
lines changed

3 files changed

+187
-25
lines changed

‎sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java

+11-12
Original file line numberDiff line numberDiff line change
@@ -139,13 +139,17 @@ public AndroidProfiler(
139139
frameMetricsCollectorId =
140140
frameMetricsCollector.startCollection(
141141
new SentryFrameMetricsCollector.FrameMetricsCollectorListener() {
142-
final long nanosInSecond = TimeUnit.SECONDS.toNanos(1);
143-
final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700);
144142
float lastRefreshRate = 0;
145143

146144
@Override
147145
public void onFrameMetricCollected(
148-
final long frameEndNanos, final long durationNanos, float refreshRate) {
146+
final long frameStartNanos,
147+
final long frameEndNanos,
148+
final long durationNanos,
149+
final long delayNanos,
150+
final boolean isSlow,
151+
final boolean isFrozen,
152+
final float refreshRate) {
149153
// transactionStartNanos is calculated through SystemClock.elapsedRealtimeNanos(),
150154
// but frameEndNanos uses System.nanotime(), so we convert it to get the timestamp
151155
// relative to transactionStartNanos
@@ -160,22 +164,17 @@ public void onFrameMetricCollected(
160164
if (frameTimestampRelativeNanos < 0) {
161165
return;
162166
}
163-
// Most frames take just a few nanoseconds longer than the optimal calculated
164-
// duration.
165-
// Therefore we subtract one, because otherwise almost all frames would be slow.
166-
boolean isSlow = durationNanos > nanosInSecond / (refreshRate - 1);
167-
float newRefreshRate = (int) (refreshRate * 100) / 100F;
168-
if (durationNanos > frozenFrameThresholdNanos) {
167+
if (isFrozen) {
169168
frozenFrameRenderMeasurements.addLast(
170169
new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos));
171170
} else if (isSlow) {
172171
slowFrameRenderMeasurements.addLast(
173172
new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos));
174173
}
175-
if (newRefreshRate != lastRefreshRate) {
176-
lastRefreshRate = newRefreshRate;
174+
if (refreshRate != lastRefreshRate) {
175+
lastRefreshRate = refreshRate;
177176
screenFrameRateMeasurements.addLast(
178-
new ProfileMeasurementValue(frameTimestampRelativeNanos, newRefreshRate));
177+
new ProfileMeasurementValue(frameTimestampRelativeNanos, refreshRate));
179178
}
180179
}
181180
});

‎sentry-android-core/src/main/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollector.java

+41-3
Original file line numberDiff line numberDiff line change
@@ -25,12 +25,16 @@
2525
import java.util.UUID;
2626
import java.util.concurrent.ConcurrentHashMap;
2727
import java.util.concurrent.CopyOnWriteArraySet;
28+
import java.util.concurrent.TimeUnit;
2829
import org.jetbrains.annotations.ApiStatus;
2930
import org.jetbrains.annotations.NotNull;
3031
import org.jetbrains.annotations.Nullable;
3132

3233
@ApiStatus.Internal
3334
public final class SentryFrameMetricsCollector implements Application.ActivityLifecycleCallbacks {
35+
private static final long oneSecondInNanos = TimeUnit.SECONDS.toNanos(1);
36+
private static final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700);
37+
3438
private final @NotNull BuildInfoProvider buildInfoProvider;
3539
private final @NotNull Set<Window> trackedWindows = new CopyOnWriteArraySet<>();
3640
private final @NotNull ILogger logger;
@@ -132,6 +136,7 @@ public SentryFrameMetricsCollector(
132136
logger.log(
133137
SentryLevel.ERROR, "Unable to get the frame timestamp from the choreographer: ", e);
134138
}
139+
135140
frameMetricsAvailableListener =
136141
(window, frameMetrics, dropCountSinceLastInvocation) -> {
137142
final long now = System.nanoTime();
@@ -140,6 +145,13 @@ public SentryFrameMetricsCollector(
140145
? window.getContext().getDisplay().getRefreshRate()
141146
: window.getWindowManager().getDefaultDisplay().getRefreshRate();
142147

148+
final long expectedFrameDuration = (long) (oneSecondInNanos / refreshRate);
149+
final long totalFrameDuration = frameMetrics.getMetric(FrameMetrics.TOTAL_DURATION);
150+
151+
// if totalDurationNanos is smaller than expectedFrameTimeNanos,
152+
// it means that the frame was drawn within it's time budget, thus 0 delay
153+
final long delayNanos = Math.max(0, totalFrameDuration - expectedFrameDuration);
154+
143155
final long cpuDuration = getFrameCpuDuration(frameMetrics);
144156
long startTime = getFrameStartTimestamp(frameMetrics);
145157
// If we couldn't get the timestamp through reflection, we use current time
@@ -155,8 +167,21 @@ public SentryFrameMetricsCollector(
155167
lastFrameStartNanos = startTime;
156168
lastFrameEndNanos = startTime + cpuDuration;
157169

170+
// Most frames take just a few nanoseconds longer than the optimal calculated
171+
// duration.
172+
// Therefore we subtract one, because otherwise almost all frames would be slow.
173+
final boolean isSlow = cpuDuration > oneSecondInNanos / (refreshRate - 1);
174+
final boolean isFrozen = isSlow && cpuDuration > frozenFrameThresholdNanos;
175+
158176
for (FrameMetricsCollectorListener l : listenerMap.values()) {
159-
l.onFrameMetricCollected(lastFrameEndNanos, cpuDuration, refreshRate);
177+
l.onFrameMetricCollected(
178+
startTime,
179+
lastFrameEndNanos,
180+
cpuDuration,
181+
delayNanos,
182+
isSlow,
183+
isFrozen,
184+
refreshRate);
160185
}
161186
};
162187
}
@@ -299,13 +324,26 @@ public interface FrameMetricsCollectorListener {
299324
/**
300325
* Called when a frame is collected.
301326
*
327+
* @param frameStartNanos Start timestamp of a frame in nanoseconds relative to
328+
* System.nanotime().
302329
* @param frameEndNanos End timestamp of a frame in nanoseconds relative to System.nanotime().
303330
* @param durationNanos Duration in nanoseconds of the time spent from the cpu on the main
304331
* thread to create the frame.
305-
* @param refreshRate Refresh rate of the screen.
332+
* @param delayNanos the frame delay, in nanoseconds.
333+
* @param isSlow True if the frame is considered slow, rendering taking longer than the
334+
* refresh-rate based budget, false otherwise.
335+
* @param isFrozen True if the frame is considered frozen, rendering taking longer than 700ms,
336+
* false otherwise.
337+
* @param refreshRate the last known refresh rate when the frame was rendered.
306338
*/
307339
void onFrameMetricCollected(
308-
final long frameEndNanos, final long durationNanos, final float refreshRate);
340+
final long frameStartNanos,
341+
final long frameEndNanos,
342+
final long durationNanos,
343+
final long delayNanos,
344+
final boolean isSlow,
345+
final boolean isFrozen,
346+
final float refreshRate);
309347
}
310348

311349
@ApiStatus.Internal

‎sentry-android-core/src/test/java/io/sentry/android/core/internal/util/SentryFrameMetricsCollectorTest.kt

+135-10
Original file line numberDiff line numberDiff line change
@@ -25,12 +25,15 @@ import org.mockito.kotlin.whenever
2525
import org.robolectric.Shadows
2626
import java.lang.ref.WeakReference
2727
import java.lang.reflect.Field
28+
import java.util.concurrent.TimeUnit
2829
import kotlin.test.BeforeTest
2930
import kotlin.test.Test
3031
import kotlin.test.assertEquals
3132
import kotlin.test.assertFailsWith
33+
import kotlin.test.assertFalse
3234
import kotlin.test.assertNotNull
3335
import kotlin.test.assertNull
36+
import kotlin.test.assertTrue
3437

3538
@RunWith(AndroidJUnit4::class)
3639
class SentryFrameMetricsCollectorTest {
@@ -280,7 +283,10 @@ class SentryFrameMetricsCollectorTest {
280283
val frameMetrics = createMockFrameMetrics()
281284

282285
var timesCalled = 0
283-
collector.startCollection { frameEndNanos, durationNanos, refreshRate ->
286+
collector.startCollection { frameStartNanos, frameEndNanos,
287+
durationNanos, delayNanos,
288+
isSlow, isFrozen,
289+
refreshRate ->
284290
// The frame end is 100 (Choreographer.mLastFrameTimeNanos) plus frame duration
285291
assertEquals(100 + durationNanos, frameEndNanos)
286292
timesCalled++
@@ -297,12 +303,14 @@ class SentryFrameMetricsCollectorTest {
297303
}
298304
val collector = fixture.getSut(context, buildInfo)
299305
val listener = collector.getProperty<Window.OnFrameMetricsAvailableListener>("frameMetricsAvailableListener")
300-
// FrameMetrics with cpu time of 21 nanoseconds and INTENDED_VSYNC_TIMESTAMP of 50 nanoseconds
301306
val frameMetrics = createMockFrameMetrics()
302307
// We don't inject the choreographer field
303308

304309
var timesCalled = 0
305-
collector.startCollection { frameEndNanos, durationNanos, refreshRate ->
310+
collector.startCollection { frameStartNanos, frameEndNanos,
311+
durationNanos, delayNanos,
312+
isSlow, isFrozen,
313+
refreshRate ->
306314
assertEquals(50 + durationNanos, frameEndNanos)
307315
timesCalled++
308316
}
@@ -322,7 +330,10 @@ class SentryFrameMetricsCollectorTest {
322330
val frameMetrics = createMockFrameMetrics()
323331

324332
var timesCalled = 0
325-
collector.startCollection { frameEndNanos, durationNanos, refreshRate ->
333+
collector.startCollection { frameStartNanos, frameEndNanos,
334+
durationNanos, delayNanos,
335+
isSlow, isFrozen,
336+
refreshRate ->
326337
assertEquals(21, durationNanos)
327338
timesCalled++
328339
}
@@ -342,7 +353,10 @@ class SentryFrameMetricsCollectorTest {
342353
whenever(frameMetrics.getMetric(FrameMetrics.INTENDED_VSYNC_TIMESTAMP)).thenReturn(50)
343354
var previousEnd = 0L
344355
var timesCalled = 0
345-
collector.startCollection { frameEndNanos, durationNanos, refreshRate ->
356+
collector.startCollection { frameStartNanos, frameEndNanos,
357+
durationNanos, delayNanos,
358+
isSlow, isFrozen,
359+
refreshRate ->
346360
// The second time the listener is called, the frame start is shifted to be equal to the previous frame end
347361
if (timesCalled > 0) {
348362
assertEquals(previousEnd + durationNanos, frameEndNanos)
@@ -356,25 +370,136 @@ class SentryFrameMetricsCollectorTest {
356370
assertEquals(2, timesCalled)
357371
}
358372

359-
private fun createMockWindow(): Window {
373+
@Test
374+
fun `collector properly reports slow and frozen flags`() {
375+
val buildInfo = mock<BuildInfoProvider> {
376+
whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O)
377+
}
378+
val collector = fixture.getSut(context, buildInfo)
379+
val listener = collector.getProperty<Window.OnFrameMetricsAvailableListener>("frameMetricsAvailableListener")
380+
381+
var timesCalled = 0
382+
var lastIsSlow = false
383+
var lastIsFrozen = false
384+
385+
// when a frame takes less than 16ms, it's not considered slow or frozen
386+
collector.startCollection { _, _,
387+
_, _,
388+
isSlow, isFrozen,
389+
_ ->
390+
391+
lastIsSlow = isSlow
392+
lastIsFrozen = isFrozen
393+
timesCalled++
394+
}
395+
listener.onFrameMetricsAvailable(createMockWindow(), createMockFrameMetrics(), 0)
396+
assertFalse(lastIsSlow)
397+
assertFalse(lastIsFrozen)
398+
399+
// when a frame takes more than 16ms, it's considered slow but not frozen
400+
listener.onFrameMetricsAvailable(
401+
createMockWindow(),
402+
createMockFrameMetrics(
403+
unknownDelayDuration = 1 + TimeUnit.MILLISECONDS.toNanos(100)
404+
),
405+
0
406+
)
407+
assertTrue(lastIsSlow)
408+
assertFalse(lastIsFrozen)
409+
410+
// when a frame takes more than 700ms, it's considered slow and frozen
411+
listener.onFrameMetricsAvailable(
412+
createMockWindow(),
413+
createMockFrameMetrics(
414+
unknownDelayDuration = 1 + TimeUnit.MILLISECONDS.toNanos(1000)
415+
),
416+
0
417+
)
418+
assertTrue(lastIsSlow)
419+
assertTrue(lastIsFrozen)
420+
421+
// Assert the callbacks were called
422+
assertEquals(3, timesCalled)
423+
}
424+
425+
@Test
426+
fun `collector properly reports frame delay`() {
427+
val buildInfo = mock<BuildInfoProvider> {
428+
whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.O)
429+
}
430+
val collector = fixture.getSut(context, buildInfo)
431+
val listener = collector.getProperty<Window.OnFrameMetricsAvailableListener>("frameMetricsAvailableListener")
432+
433+
var lastDelay = 0L
434+
435+
// when a frame takes less than 16ms, it's not considered slow or frozen
436+
collector.startCollection { _, _,
437+
_, delayNanos,
438+
isSlow, isFrozen,
439+
_ ->
440+
lastDelay = delayNanos
441+
}
442+
// at 60hz, when the total duration is 10ms, the delay is 0
443+
listener.onFrameMetricsAvailable(
444+
createMockWindow(),
445+
createMockFrameMetrics(
446+
totalDuration = TimeUnit.MILLISECONDS.toNanos(16)
447+
),
448+
0
449+
)
450+
assertEquals(0, lastDelay)
451+
452+
// at 60hz, when the total duration is 20ms, the delay is considered ~4ms
453+
listener.onFrameMetricsAvailable(
454+
createMockWindow(),
455+
createMockFrameMetrics(
456+
totalDuration = TimeUnit.MILLISECONDS.toNanos(20)
457+
),
458+
0
459+
)
460+
assertEquals(
461+
// 20ms - 1/60 (~16.6ms) = 4ms
462+
TimeUnit.MILLISECONDS.toNanos(20) - (TimeUnit.SECONDS.toNanos(1) / 60.0f).toLong(),
463+
lastDelay
464+
)
465+
466+
// at 120hz, when the total duration is 20ms, the delay is considered ~8ms
467+
listener.onFrameMetricsAvailable(
468+
createMockWindow(120.0f),
469+
createMockFrameMetrics(
470+
totalDuration = TimeUnit.MILLISECONDS.toNanos(20)
471+
),
472+
0
473+
)
474+
assertEquals(
475+
// 20ms - 1/120 (~8.33ms) = 8ms
476+
TimeUnit.MILLISECONDS.toNanos(20) - (TimeUnit.SECONDS.toNanos(1) / 120.0f).toLong(),
477+
lastDelay
478+
)
479+
}
480+
481+
private fun createMockWindow(refreshRate: Float = 60F): Window {
360482
val mockWindow = mock<Window>()
361483
val mockDisplay = mock<Display>()
362484
val mockWindowManager = mock<WindowManager>()
363485
whenever(mockWindow.windowManager).thenReturn(mockWindowManager)
364486
whenever(mockWindowManager.defaultDisplay).thenReturn(mockDisplay)
365-
whenever(mockDisplay.refreshRate).thenReturn(60F)
487+
whenever(mockDisplay.refreshRate).thenReturn(refreshRate)
366488
return mockWindow
367489
}
368490

369-
private fun createMockFrameMetrics(): FrameMetrics {
491+
/**
492+
* FrameMetrics with default cpu time of 21 nanoseconds and INTENDED_VSYNC_TIMESTAMP of 50 nanoseconds
493+
*/
494+
private fun createMockFrameMetrics(unknownDelayDuration: Long = 1, totalDuration: Long = 60): FrameMetrics {
370495
val frameMetrics = mock<FrameMetrics>()
371-
whenever(frameMetrics.getMetric(FrameMetrics.UNKNOWN_DELAY_DURATION)).thenReturn(1)
496+
whenever(frameMetrics.getMetric(FrameMetrics.UNKNOWN_DELAY_DURATION)).thenReturn(unknownDelayDuration)
372497
whenever(frameMetrics.getMetric(FrameMetrics.INPUT_HANDLING_DURATION)).thenReturn(2)
373498
whenever(frameMetrics.getMetric(FrameMetrics.ANIMATION_DURATION)).thenReturn(3)
374499
whenever(frameMetrics.getMetric(FrameMetrics.LAYOUT_MEASURE_DURATION)).thenReturn(4)
375500
whenever(frameMetrics.getMetric(FrameMetrics.DRAW_DURATION)).thenReturn(5)
376501
whenever(frameMetrics.getMetric(FrameMetrics.SYNC_DURATION)).thenReturn(6)
377-
whenever(frameMetrics.getMetric(FrameMetrics.TOTAL_DURATION)).thenReturn(60)
502+
whenever(frameMetrics.getMetric(FrameMetrics.TOTAL_DURATION)).thenReturn(totalDuration)
378503
whenever(frameMetrics.getMetric(FrameMetrics.INTENDED_VSYNC_TIMESTAMP)).thenReturn(50)
379504
return frameMetrics
380505
}

0 commit comments

Comments
 (0)