diff --git a/CHANGELOG.md b/CHANGELOG.md index 5ff6b1f542e..9ab6f115349 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -24,6 +24,7 @@ - Session Replay: Fix `SentryOkHttpInterceptor` hanging forever on responses whose body has no known length, such as Server-Sent Events or a gzipped response, when network details are enabled for the URL ([#6231](https://github.com/getsentry/sentry-java/pull/6231)) - Session Replay: `SentryOkHttpInterceptor` now captures network request and response details only while Session Replay is recording or buffering ([#6486](https://github.com/getsentry/sentry-java/pull/6486)) - Stop marking an OkHttp call span as failed when a connection attempt to one of the host's addresses fails but OkHttp connects on another ([#6472](https://github.com/getsentry/sentry-java/pull/6472)) +- Place wall-clock-stamped spans, such as app start spans, on the frame timeline using a fixed anchor, so that a device time change or time spent suspended no longer shifts the frame data attributed to them ([#6098](https://github.com/getsentry/sentry-java/pull/6098)) ### Dependencies 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 074a4a6ea51..69711f72a25 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 @@ -1,6 +1,5 @@ package io.sentry.android.core; -import io.sentry.DateUtils; import io.sentry.IPerformanceContinuousCollector; import io.sentry.ISentryLifecycleToken; import io.sentry.ISpan; @@ -12,6 +11,10 @@ import io.sentry.SpanDataConvention; import io.sentry.android.core.internal.util.SentryFrameMetricsCollector; import io.sentry.protocol.MeasurementValue; +import io.sentry.time.EpochClock; +import io.sentry.time.JavaMonotonicTicker; +import io.sentry.time.MonotonicTicker; +import io.sentry.time.SystemEpochClock; import io.sentry.util.AutoClosableReentrantLock; import java.util.Iterator; import java.util.SortedSet; @@ -68,12 +71,34 @@ public class SpanFrameMetricsCollector // assume 60fps until we get a value reported by the system private long lastKnownFrameDurationNanos = 16_666_666L; + // The frame timeline minus the wall clock, read once at construction. Reading it again later + // would pick up every wall-clock step and every suspend since (System.nanoTime() stops in + // suspend, the wall clock does not), and shift wall-stamped spans away from their frames. + private final long frameTimelineOffsetNanos; + public SpanFrameMetricsCollector( final @NotNull SentryAndroidOptions options, final @NotNull SentryFrameMetricsCollector frameMetricsCollector) { + // Deliberately not options.getMonotonicTicker(), which is elapsedRealtimeNanos on Android: + // frames are stamped by Choreographer on System.nanoTime(), and the two bases drift apart by + // however long the device spends suspended. + this( + options, + frameMetricsCollector, + SystemEpochClock.getInstance(), + JavaMonotonicTicker.getInstance()); + } + + SpanFrameMetricsCollector( + final @NotNull SentryAndroidOptions options, + final @NotNull SentryFrameMetricsCollector frameMetricsCollector, + final @NotNull EpochClock epochClock, + final @NotNull MonotonicTicker frameTicker) { this.frameMetricsCollector = frameMetricsCollector; enabled = options.isEnablePerformanceV2() && options.isEnableFramesTracking(); + + this.frameTimelineOffsetNanos = frameTicker.tickNanos() - epochClock.now().epochNanos(); } @Override @@ -312,18 +337,16 @@ private static int addPendingFrameDelay( * @param date the input date * @return a non-unix timestamp in nano precision, similar to {@link System#nanoTime()}. */ - private static long toNanoTime(final @NotNull SentryDate date) { + private long toNanoTime(final @NotNull SentryDate date) { // SentryNanotimeDate nanotime is based on System.nanotime(), like EMPTY_NANO_TIME, // thus diff will simply return the System.nanotime() value of date if (date instanceof SentryNanotimeDate) { return date.diff(EMPTY_NANO_TIME); } - // e.g. SentryLongDate is unix time based - upscaled to nanos, - // we need to project it back to System.nanotime() format - long nowUnixInNanos = DateUtils.millisToNanos(System.currentTimeMillis()); - long shiftInNanos = nowUnixInNanos - date.nanoTimestamp(); - return System.nanoTime() - shiftInNanos; + // e.g. SentryLongDate is unix time based - upscaled to nanos, we need to project it onto the + // frame timeline + return date.nanoTimestamp() + frameTimelineOffsetNanos; } private static class Frame implements Comparable { 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 2b6f19a8d31..fbcb568433f 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 @@ -4,10 +4,15 @@ import io.sentry.ISpan import io.sentry.ITransaction import io.sentry.NoOpSpan import io.sentry.NoOpTransaction +import io.sentry.SentryLongDate import io.sentry.SentryNanotimeDate import io.sentry.SpanContext +import io.sentry.SpanDataConvention import io.sentry.android.core.internal.util.SentryFrameMetricsCollector import io.sentry.protocol.MeasurementValue +import io.sentry.time.EpochClock +import io.sentry.time.TestMonotonicTicker +import io.sentry.time.Timestamp import java.util.UUID import java.util.concurrent.TimeUnit import kotlin.test.Test @@ -84,6 +89,44 @@ class SpanFrameMetricsCollectorTest { private val fixture = Fixture() + @Test + fun `a wall-clock span is placed on the frame timeline using the anchor taken at construction`() { + // app start spans are SentryLongDates, stamped on the wall clock rather than on nanoTime + val anchorEpochNanos = TimeUnit.SECONDS.toNanos(1_600_000_000) + val frameTicker = TestMonotonicTicker() + + whenever(fixture.frameMetricsCollector.startCollection(any())) + .thenReturn(UUID.randomUUID().toString()) + whenever(fixture.frameMetricsCollector.getLastKnownFrameStartTimeNanos()).thenReturn(-1) + fixture.options.frameMetricsCollector = fixture.frameMetricsCollector + fixture.options.isEnableFramesTracking = true + fixture.options.isEnablePerformanceV2 = true + + val sut = + SpanFrameMetricsCollector( + fixture.options, + fixture.frameMetricsCollector, + EpochClock { Timestamp.ofEpochNanos(anchorEpochNanos) }, + frameTicker, + ) + + val span = mock() + whenever(span.spanContext).thenReturn(SpanContext("op.fake")) + whenever(span.startDate).thenReturn(SentryLongDate(anchorEpochNanos + 1_000)) + whenever(span.finishDate).thenReturn(SentryLongDate(anchorEpochNanos + 100_000_000)) + + sut.onSpanStarted(span) + // one slow frame, on the frame timeline, fully inside the span + sut.onFrameMetricCollected(2_000, 50_000_000, 49_998_000, 30_000_000, true, false, 60.0f) + + // the device spends an hour suspended before the span finishes, so the offset between the + // wall clock and the frame timeline is no longer what it was when the span started + frameTicker.advance(1, TimeUnit.HOURS) + sut.onSpanFinished(span) + + verify(span).setData(SpanDataConvention.FRAMES_SLOW, 1) + } + @Test fun `When AndroidSlowFrozenFrameCollector is initialized, it doesn't register any listener`() { fixture.getSut()