diff --git a/CHANGELOG.md b/CHANGELOG.md index 09622493a2..3acb4a210b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Fixes + +- 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)) + ## 8.56.0 ### Behavioral Changes 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 074a4a6ea5..5f575eb38a 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,35 @@ public class SpanFrameMetricsCollector // assume 60fps until we get a value reported by the system private long lastKnownFrameDurationNanos = 16_666_666L; + // One wall-clock reading paired with one tick, both taken at construction, used to place + // wall-stamped span dates on the frame timeline. See toNanoTime. + private final long wallAnchorNanos; + private final long tickAnchorNanos; + 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.wallAnchorNanos = epochClock.now().epochNanos(); + this.tickAnchorNanos = frameTicker.tickNanos(); } @Override @@ -312,18 +338,22 @@ 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, so it has to be projected onto + // the frame timeline. That projection needs the offset between the two clocks, and the offset + // is only a constant while nothing disturbs either of them: a wall-clock step moves one, and + // time spent suspended moves the other, since System.nanoTime() stops in suspend and the wall + // clock does not. Reading the offset here, whenever a span happens to finish, would therefore + // charge the span for every step and every suspend since it started - an app start span can + // be projected hours away from the frames it actually overlapped. Hold the offset from + // construction instead, so a span lands where it did when the SDK started. + return tickAnchorNanos + (date.nanoTimestamp() - wallAnchorNanos); } 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 2b6f19a8d3..fbcb568433 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()