Skip to content

Commit a33b076

Browse files
stefanosianostefanosiano
authored
Fix Frame measurements in app start transactions (#3382)
* 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
1 parent 0156268 commit a33b076

File tree

8 files changed

+113
-12
lines changed

8 files changed

+113
-12
lines changed

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@
88

99
### Fixes
1010

11+
- Fix Frame measurements in app start transactions ([#3382](https://github.com/getsentry/sentry-java/pull/3382))
1112
- Fix timing metric value different from span duration ([#3368](https://github.com/getsentry/sentry-java/pull/3368))
1213

1314
## 7.8.0

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

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
import io.sentry.NoOpTransaction;
88
import io.sentry.SentryDate;
99
import io.sentry.SentryNanotimeDate;
10+
import io.sentry.SentryTracer;
1011
import io.sentry.SpanDataConvention;
1112
import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
1213
import io.sentry.protocol.MeasurementValue;
@@ -135,11 +136,15 @@ private void captureFrameMetrics(@NotNull final ISpan span) {
135136
return;
136137
}
137138

138-
// ignore spans with no finish date
139-
final @Nullable SentryDate spanFinishDate = span.getFinishDate();
139+
// Ignore spans with no finish date, but SentryTracer is not finished when executing this
140+
// callback, yet, so in that case we use the current timestamp.
141+
final @Nullable SentryDate spanFinishDate =
142+
span instanceof SentryTracer ? new SentryNanotimeDate() : span.getFinishDate();
140143
if (spanFinishDate == null) {
141144
return;
142145
}
146+
// Note: The comparison between two values obtained by realNanos() works only if both are the
147+
// same kind of dates (both are SentryNanotimeDate or both SentryLongDate)
143148
final long spanEndNanos = realNanos(spanFinishDate);
144149

145150
final @NotNull SentryFrameMetrics frameMetrics = new SentryFrameMetrics();

‎sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,8 @@
44
import io.sentry.DateUtils;
55
import io.sentry.SentryDate;
66
import io.sentry.SentryLongDate;
7+
import io.sentry.SentryNanotimeDate;
8+
import java.util.concurrent.TimeUnit;
79
import org.jetbrains.annotations.ApiStatus;
810
import org.jetbrains.annotations.NotNull;
911
import org.jetbrains.annotations.Nullable;
@@ -21,6 +23,7 @@ public class TimeSpan implements Comparable<TimeSpan> {
2123

2224
private @Nullable String description;
2325

26+
private long startSystemNanos;
2427
private long startUnixTimeMs;
2528
private long startUptimeMs;
2629
private long stopUptimeMs;
@@ -29,6 +32,7 @@ public class TimeSpan implements Comparable<TimeSpan> {
2932
public void start() {
3033
startUptimeMs = SystemClock.uptimeMillis();
3134
startUnixTimeMs = System.currentTimeMillis();
35+
startSystemNanos = System.nanoTime();
3236
}
3337

3438
/**
@@ -40,6 +44,7 @@ public void setStartedAt(final long uptimeMs) {
4044

4145
final long shiftMs = SystemClock.uptimeMillis() - startUptimeMs;
4246
startUnixTimeMs = System.currentTimeMillis() - shiftMs;
47+
startSystemNanos = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(shiftMs);
4348
}
4449

4550
/** Stops the time span */
@@ -90,7 +95,8 @@ public long getStartTimestampMs() {
9095
*/
9196
public @Nullable SentryDate getStartTimestamp() {
9297
if (hasStarted()) {
93-
return new SentryLongDate(DateUtils.millisToNanos(getStartTimestampMs()));
98+
return new SentryNanotimeDate(
99+
DateUtils.nanosToDate(DateUtils.millisToNanos(getStartTimestampMs())), startSystemNanos);
94100
}
95101
return null;
96102
}
@@ -162,6 +168,7 @@ public void reset() {
162168
startUptimeMs = 0;
163169
stopUptimeMs = 0;
164170
startUnixTimeMs = 0;
171+
startSystemNanos = 0;
165172
}
166173

167174
@Override

‎sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -40,9 +40,7 @@ class SpanFrameMetricsCollectorTest {
4040
options.frameMetricsCollector = frameMetricsCollector
4141
options.isEnableFramesTracking = enabled
4242
options.isEnablePerformanceV2 = enabled
43-
options.setDateProvider {
44-
SentryLongDate(timeNanos)
45-
}
43+
options.dateProvider = SentryAndroidDateProvider()
4644

4745
return SpanFrameMetricsCollector(options, frameMetricsCollector)
4846
}

‎sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt‎

Lines changed: 90 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,13 +2,23 @@ package io.sentry.uitest.android
22

33
import androidx.lifecycle.Lifecycle
44
import androidx.test.core.app.launchActivity
5+
import androidx.test.espresso.Espresso
6+
import androidx.test.espresso.IdlingRegistry
7+
import androidx.test.espresso.action.ViewActions
8+
import androidx.test.espresso.matcher.ViewMatchers
59
import androidx.test.ext.junit.runners.AndroidJUnit4
610
import io.sentry.Sentry
711
import io.sentry.SentryLevel
12+
import io.sentry.android.core.AndroidLogger
813
import io.sentry.android.core.SentryAndroidOptions
14+
import io.sentry.assertEnvelopeTransaction
15+
import io.sentry.protocol.MeasurementValue
916
import io.sentry.protocol.SentryTransaction
17+
import org.junit.Assume
1018
import org.junit.runner.RunWith
1119
import kotlin.test.Test
20+
import kotlin.test.assertEquals
21+
import kotlin.test.assertNotEquals
1222
import kotlin.test.assertTrue
1323

1424
@RunWith(AndroidJUnit4::class)
@@ -49,4 +59,84 @@ class AutomaticSpansTest : BaseUiTest() {
4959
}
5060
}
5161
}
62+
63+
@Test
64+
fun checkAppStartFramesMeasurements() {
65+
initSentry(true) { options: SentryAndroidOptions ->
66+
options.tracesSampleRate = 1.0
67+
options.isEnableTimeToFullDisplayTracing = true
68+
options.isEnablePerformanceV2 = false
69+
}
70+
71+
IdlingRegistry.getInstance().register(ProfilingSampleActivity.scrollingIdlingResource)
72+
val sampleScenario = launchActivity<ProfilingSampleActivity>()
73+
swipeList(3)
74+
Sentry.reportFullyDisplayed()
75+
sampleScenario.moveToState(Lifecycle.State.DESTROYED)
76+
IdlingRegistry.getInstance().unregister(ProfilingSampleActivity.scrollingIdlingResource)
77+
relayIdlingResource.increment()
78+
79+
relay.assert {
80+
findEnvelope {
81+
assertEnvelopeTransaction(it.items.toList(), AndroidLogger()).transaction == "ProfilingSampleActivity"
82+
}.assert {
83+
val transactionItem: SentryTransaction = it.assertTransaction()
84+
it.assertNoOtherItems()
85+
val measurements = transactionItem.measurements
86+
val frozenFrames = measurements[MeasurementValue.KEY_FRAMES_FROZEN]?.value?.toInt() ?: 0
87+
val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0
88+
val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0
89+
assertEquals("ProfilingSampleActivity", transactionItem.transaction)
90+
// AGP matrix tests have no frames
91+
Assume.assumeTrue(totalFrames > 0)
92+
assertNotEquals(totalFrames, 0)
93+
assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.")
94+
}
95+
assertNoOtherEnvelopes()
96+
}
97+
}
98+
99+
@Test
100+
fun checkAppStartFramesMeasurementsPerfV2() {
101+
initSentry(true) { options: SentryAndroidOptions ->
102+
options.tracesSampleRate = 1.0
103+
options.isEnableTimeToFullDisplayTracing = true
104+
options.isEnablePerformanceV2 = true
105+
}
106+
107+
IdlingRegistry.getInstance().register(ProfilingSampleActivity.scrollingIdlingResource)
108+
val sampleScenario = launchActivity<ProfilingSampleActivity>()
109+
swipeList(3)
110+
Sentry.reportFullyDisplayed()
111+
sampleScenario.moveToState(Lifecycle.State.DESTROYED)
112+
IdlingRegistry.getInstance().unregister(ProfilingSampleActivity.scrollingIdlingResource)
113+
relayIdlingResource.increment()
114+
115+
relay.assert {
116+
findEnvelope {
117+
assertEnvelopeTransaction(it.items.toList(), AndroidLogger()).transaction == "ProfilingSampleActivity"
118+
}.assert {
119+
val transactionItem: SentryTransaction = it.assertTransaction()
120+
it.assertNoOtherItems()
121+
val measurements = transactionItem.measurements
122+
val frozenFrames = measurements[MeasurementValue.KEY_FRAMES_FROZEN]?.value?.toInt() ?: 0
123+
val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0
124+
val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0
125+
assertEquals("ProfilingSampleActivity", transactionItem.transaction)
126+
// AGP matrix tests have no frames
127+
Assume.assumeTrue(totalFrames > 0)
128+
assertNotEquals(totalFrames, 0)
129+
assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.")
130+
}
131+
assertNoOtherEnvelopes()
132+
}
133+
}
134+
135+
private fun swipeList(times: Int) {
136+
repeat(times) {
137+
Thread.sleep(100)
138+
Espresso.onView(ViewMatchers.withId(R.id.profiling_sample_list)).perform(ViewActions.swipeUp())
139+
Espresso.onIdle()
140+
}
141+
}
52142
}

‎sentry-android-integration-tests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -157,7 +157,7 @@ class EnvelopeTests : BaseUiTest() {
157157
// Timestamps of measurements should differ at least 10 milliseconds from each other
158158
(1 until values.size).forEach { i ->
159159
assertTrue(
160-
values[i].relativeStartNs.toLong() > values[i - 1].relativeStartNs.toLong() + TimeUnit.MILLISECONDS.toNanos(
160+
values[i].relativeStartNs.toLong() >= values[i - 1].relativeStartNs.toLong() + TimeUnit.MILLISECONDS.toNanos(
161161
10
162162
),
163163
"Measurement value timestamp for '$name' does not differ at least 10ms"

‎sentry/src/main/java/io/sentry/SentryTracer.java‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -87,9 +87,9 @@ public SentryTracer(
8787
this.baggage = new Baggage(hub.getOptions().getLogger());
8888
}
8989

90-
// We are currently sending the performance data only in profiles, so there's no point in
91-
// collecting them if a profile is not sampled
92-
if (transactionPerformanceCollector != null && Boolean.TRUE.equals(isProfileSampled())) {
90+
// We are currently sending the performance data only in profiles, but we are always sending
91+
// performance measurements.
92+
if (transactionPerformanceCollector != null) {
9393
transactionPerformanceCollector.start(this);
9494
}
9595

‎sentry/src/test/java/io/sentry/SentryTracerTest.kt‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1005,9 +1005,9 @@ class SentryTracerTest {
10051005
}
10061006

10071007
@Test
1008-
fun `when transaction is created, but not profiled, transactionPerformanceCollector is not started`() {
1008+
fun `when transaction is created, but not profiled, transactionPerformanceCollector is started anyway`() {
10091009
val transaction = fixture.getSut()
1010-
verify(fixture.transactionPerformanceCollector, never()).start(anyOrNull())
1010+
verify(fixture.transactionPerformanceCollector).start(anyOrNull())
10111011
}
10121012

10131013
@Test

0 commit comments

Comments
 (0)