Skip to content

Commit 1870a9c

Browse files
committed
feat(time): Anchor span timestamps on one wall-clock reading (JAVA-572)
Demonstrates what AnchoredClock and Timestamp look like once Span and SentryTracer actually use them. Not for merge before the major: it changes a serialized value. SentryTracer takes one epoch reading when it is constructed, pins it to one monotonic tick, and every span below it projects from that anchor rather than reading the wall clock again. Because the projection is affine with slope 1, subtracting any two instants in a transaction is subtracting two ticks, so serialization no longer derives anything: - this.timestamp = DateUtils.nanosToSeconds( - span.getStartDate().laterDateNanosTimestampByDiff(span.getFinishDate())); + this.timestamp = DateUtils.nanosToSeconds(span.endTimestamp().epochNanos()); That is the whole point. laterDateNanosTimestampByDiff exists to rescue a monotonic end out of two dates whose classes happen to cooperate; with one anchor there is nothing to rescue. The two sites that reverse-engineered the hidden System.nanoTime() tick out of SentryNanotimeDate ask the anchor instead, and both sentinels -- SentryNanotimeDate(0, 0) -- are gone. DriverSpans.computeNanoStartTimestampForChild collapses to anchor().now(), and no longer silently drops to millisecond precision when the parent's date is not the class it hoped for. ISpan gains startTimestamp(), endTimestamp() and anchor(). getStartDate() and getFinishDate() stay, as epoch-only views, so the public API still works; at the major they go and the SentryDate overloads of finish() and updateEndDate() go with them. Spans whose instants come from outside the process -- OTel, an app-start projection, a caller-supplied startTimestamp -- report a null anchor and keep wall-clock semantics. That case cannot be improved, because the input carries nothing but an epoch; what changes is that it is now a named branch rather than an instanceof that falls through. Why this waits for the major: a child span's start_timestamp moves by sub-millisecond amounts, because it is projected rather than read. Root spans do not move, the anchor being read at root start. Two things this turned up, both left open on purpose: - The frame timebase. Choreographer reports frames on CLOCK_MONOTONIC while the anchor's tick is CLOCK_BOOTTIME on Android, so SpanFrameMetricsCollector needs an offset it cannot read from statics without becoming untestable, and a decision about spans that spanned deep sleep. Marked TODO [MAJOR] rather than half-solved. - SentryDate has no value equality, so getStartDate() returning a fresh view breaks identity comparisons. The tests here move to Timestamp, which does. Also fixes a test that stubbed dateProvider.now() as a fixed call sequence and so depended on how often unrelated code read the provider.
1 parent b50dc01 commit 1870a9c

23 files changed

Lines changed: 508 additions & 257 deletions

File tree

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

Lines changed: 37 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -7,11 +7,11 @@
77
import io.sentry.ITransaction;
88
import io.sentry.NoOpSpan;
99
import io.sentry.NoOpTransaction;
10-
import io.sentry.SentryDate;
11-
import io.sentry.SentryNanotimeDate;
1210
import io.sentry.SpanDataConvention;
1311
import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
1412
import io.sentry.protocol.MeasurementValue;
13+
import io.sentry.time.AnchoredClock;
14+
import io.sentry.time.Timestamp;
1515
import io.sentry.util.AutoClosableReentrantLock;
1616
import java.util.Iterator;
1717
import java.util.SortedSet;
@@ -32,7 +32,6 @@ public class SpanFrameMetricsCollector
3232
// grow indefinitely in case of a long running span
3333
private static final int MAX_FRAMES_COUNT = 3600;
3434
private static final long ONE_SECOND_NANOS = TimeUnit.SECONDS.toNanos(1);
35-
private static final SentryNanotimeDate EMPTY_NANO_TIME = new SentryNanotimeDate(0, 0);
3635

3736
private final boolean enabled;
3837
protected final @NotNull AutoClosableReentrantLock lock = new AutoClosableReentrantLock();
@@ -47,7 +46,8 @@ public class SpanFrameMetricsCollector
4746
if (o1 == o2) {
4847
return 0;
4948
}
50-
int timeDiff = o1.getStartDate().compareTo(o2.getStartDate());
49+
int timeDiff =
50+
Long.compare(o1.startTimestamp().epochNanos(), o2.startTimestamp().epochNanos());
5151
if (timeDiff != 0) {
5252
return timeDiff;
5353
}
@@ -126,7 +126,7 @@ public void onSpanFinished(final @NotNull ISpan span) {
126126
} else {
127127
// otherwise only remove old/irrelevant frames
128128
final @NotNull ISpan oldestSpan = runningSpans.first();
129-
frames.headSet(new Frame(toNanoTime(oldestSpan.getStartDate()))).clear();
129+
frames.headSet(new Frame(toNanoTime(oldestSpan, oldestSpan.startTimestamp()))).clear();
130130
}
131131
}
132132
}
@@ -139,13 +139,13 @@ private void captureFrameMetrics(@NotNull final ISpan span) {
139139
return;
140140
}
141141

142-
final @Nullable SentryDate spanFinishDate = span.getFinishDate();
143-
if (spanFinishDate == null) {
142+
final @Nullable Timestamp spanFinish = span.endTimestamp();
143+
if (spanFinish == null) {
144144
return;
145145
}
146146

147-
final long spanStartNanos = toNanoTime(span.getStartDate());
148-
final long spanEndNanos = toNanoTime(spanFinishDate);
147+
final long spanStartNanos = toNanoTime(span, span.startTimestamp());
148+
final long spanEndNanos = toNanoTime(span, spanFinish);
149149
final long spanDurationNanos = spanEndNanos - spanStartNanos;
150150
if (spanDurationNanos <= 0) {
151151
return;
@@ -306,23 +306,38 @@ private static int addPendingFrameDelay(
306306
}
307307

308308
/**
309-
* Because {@link SentryNanotimeDate#nanoTimestamp()} only gives you millisecond precision, but
310-
* diff does ¯\_(ツ)_/¯
309+
* Places a span instant on the frame timeline, which {@link android.view.Choreographer} reports
310+
* in the {@link System#nanoTime()} timebase.
311311
*
312-
* @param date the input date
313-
* @return a non-unix timestamp in nano precision, similar to {@link System#nanoTime()}.
312+
* <p>An anchored span's instant inverts to the exact tick it was projected from. That tick is on
313+
* {@link io.sentry.time.MonotonicTicker} — {@code CLOCK_BOOTTIME} on Android — while frames are
314+
* on {@code CLOCK_MONOTONIC}, so crossing between them costs one offset read. The offset changes
315+
* whenever the device suspends, so a span that spanned deep sleep lands wrong by the sleep; there
316+
* are no frames during sleep, so the honest fix is to skip such a span rather than to guess. That
317+
* is the follow-up this method's caller wants, not a reason to keep projecting from the wall
318+
* clock.
319+
*
320+
* @return a non-unix timestamp in nano precision, in the {@link System#nanoTime()} timebase.
314321
*/
315-
private static long toNanoTime(final @NotNull SentryDate date) {
316-
// SentryNanotimeDate nanotime is based on System.nanotime(), like EMPTY_NANO_TIME,
317-
// thus diff will simply return the System.nanotime() value of date
318-
if (date instanceof SentryNanotimeDate) {
319-
return date.diff(EMPTY_NANO_TIME);
322+
private static long toNanoTime(final @NotNull ISpan span, final @NotNull Timestamp timestamp) {
323+
final @Nullable AnchoredClock anchor = span.anchor();
324+
if (anchor != null) {
325+
// TODO [MAJOR] Cross into the frame timebase before comparing.
326+
// The tick is on io.sentry.time.MonotonicTicker, which is CLOCK_BOOTTIME on Android, while
327+
// Choreographer reports frames on CLOCK_MONOTONIC; the two differ by however long the device
328+
// has been suspended. The offset is System.nanoTime() - SystemClock.elapsedRealtimeNanos(),
329+
// but reading it from statics here is untestable and it changes on every suspend, so it needs
330+
// an injectable seam and a decision about what to do with a span that spanned deep sleep —
331+
// there are no frames during sleep, so skipping such a span is more honest than shifting it.
332+
// Left unbridged deliberately: this demonstrates the span/anchor integration, not the
333+
// timebase fix.
334+
return anchor.tickOf(timestamp);
320335
}
321336

322-
// e.g. SentryLongDate is unix time based - upscaled to nanos,
323-
// we need to project it back to System.nanotime() format
324-
long nowUnixInNanos = DateUtils.millisToNanos(System.currentTimeMillis());
325-
long shiftInNanos = nowUnixInNanos - date.nanoTimestamp();
337+
// A stated instant — an OTel span, an app-start projection, a SQLite driver span — carries no
338+
// tick at all, so there is nothing to invert and the wall clock is all we have.
339+
final long nowUnixInNanos = DateUtils.millisToNanos(System.currentTimeMillis());
340+
final long shiftInNanos = nowUnixInNanos - timestamp.epochNanos();
326341
return System.nanoTime() - shiftInNanos;
327342
}
328343

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

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1489,7 +1489,7 @@ class ActivityLifecycleIntegrationTest {
14891489
uiLoadTransaction.children.single { it.operation == ActivityLifecycleIntegration.TTID_OP }
14901490
assertTrue(ttidSpan.isFinished)
14911491
assertTrue(appStartTransaction.isFinished)
1492-
assertEquals(ttidSpan.finishDate, appStartTransaction.finishDate)
1492+
assertEquals(ttidSpan.endTimestamp(), appStartTransaction.endTimestamp())
14931493
assertEquals(
14941494
ttidSpan.measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value,
14951495
AppStartMetrics.getInstance().appStartTimeSpan.durationMs,
@@ -2077,7 +2077,7 @@ class ActivityLifecycleIntegrationTest {
20772077
runFirstDraw(view)
20782078
assertTrue(ttidSpan.isFinished)
20792079
assertTrue(ttfdSpan.isFinished)
2080-
assertEquals(ttfdSpan.finishDate, ttidSpan.finishDate)
2080+
assertEquals(ttfdSpan.endTimestamp(), ttidSpan.endTimestamp())
20812081

20822082
sut.onActivityDestroyed(activity)
20832083

@@ -2131,8 +2131,8 @@ class ActivityLifecycleIntegrationTest {
21312131
assertNotNull(ttidSpan)
21322132
assertNotNull(ttfdSpan)
21332133

2134-
assertEquals(ttidSpan.startDate, fixture.transaction.startDate)
2135-
assertEquals(ttfdSpan.startDate, fixture.transaction.startDate)
2134+
assertEquals(ttidSpan.startTimestamp(), fixture.transaction.startTimestamp())
2135+
assertEquals(ttfdSpan.startTimestamp(), fixture.transaction.startTimestamp())
21362136
}
21372137

21382138
@Test
@@ -2168,7 +2168,7 @@ class ActivityLifecycleIntegrationTest {
21682168
// the ttfd span should be trimmed to be equal to the ttid span, and the description should end
21692169
// with "-exceeded"
21702170
assertEquals(SpanStatus.DEADLINE_EXCEEDED, ttfdSpan.status)
2171-
assertEquals(ttidSpan.finishDate, ttfdSpan.finishDate)
2171+
assertEquals(ttidSpan.endTimestamp(), ttfdSpan.endTimestamp())
21722172
assertEquals(ttfdSpan.description, "Activity full display - Deadline Exceeded")
21732173
}
21742174

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

Lines changed: 36 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
package io.sentry.android.core
22

3+
import io.sentry.DateUtils
34
import io.sentry.ISpan
45
import io.sentry.ITransaction
56
import io.sentry.NoOpSpan
@@ -8,6 +9,10 @@ import io.sentry.SentryNanotimeDate
89
import io.sentry.SpanContext
910
import io.sentry.android.core.internal.util.SentryFrameMetricsCollector
1011
import io.sentry.protocol.MeasurementValue
12+
import io.sentry.time.AnchoredClock
13+
import io.sentry.time.EpochClock
14+
import io.sentry.time.MonotonicTicker
15+
import io.sentry.time.Timestamp
1116
import java.util.UUID
1217
import java.util.concurrent.TimeUnit
1318
import kotlin.test.Test
@@ -49,16 +54,7 @@ class SpanFrameMetricsCollectorTest {
4954
val span = mock<ISpan>()
5055
val spanContext = SpanContext("op.fake")
5156
whenever(span.spanContext).thenReturn(spanContext)
52-
whenever(span.startDate)
53-
.thenReturn(SentryNanotimeDate(System.currentTimeMillis(), startTimeStampNanos))
54-
whenever(span.finishDate)
55-
.thenReturn(
56-
if (endTimeStampNanos != null) {
57-
SentryNanotimeDate(System.currentTimeMillis(), endTimeStampNanos)
58-
} else {
59-
null
60-
}
61-
)
57+
stubAnchoredTimes(span, startTimeStampNanos, endTimeStampNanos)
6258
return span
6359
}
6460

@@ -69,19 +65,39 @@ class SpanFrameMetricsCollectorTest {
6965
val span = mock<ITransaction>()
7066
val spanContext = SpanContext("op.fake")
7167
whenever(span.spanContext).thenReturn(spanContext)
72-
whenever(span.startDate)
73-
.thenReturn(SentryNanotimeDate(System.currentTimeMillis(), startTimeStampNanos))
74-
whenever(span.finishDate)
75-
.thenReturn(
76-
if (endTimeStampNanos != null) {
77-
SentryNanotimeDate(System.currentTimeMillis(), endTimeStampNanos)
78-
} else {
79-
null
80-
}
81-
)
68+
stubAnchoredTimes(span, startTimeStampNanos, endTimeStampNanos)
8269
return span
8370
}
8471

72+
/**
73+
* Gives a mocked span the timing shape a real one now has: two instants projected from one
74+
* anchor, whose ticks are the values this test feeds the frame collector.
75+
*/
76+
private fun stubAnchoredTimes(span: ISpan, startTick: Long, endTick: Long?) {
77+
val clock = FakeTicker(startTick)
78+
val epoch = EpochClock {
79+
Timestamp.ofEpochNanos(DateUtils.millisToNanos(System.currentTimeMillis()))
80+
}
81+
val anchor = AnchoredClock.create(epoch, clock)
82+
val start = anchor.origin()
83+
val end = endTick?.let {
84+
clock.setNanos(it)
85+
anchor.now()
86+
}
87+
88+
whenever(span.anchor()).thenReturn(anchor)
89+
whenever(span.startTimestamp()).thenReturn(start)
90+
whenever(span.endTimestamp()).thenReturn(end)
91+
}
92+
93+
private class FakeTicker(private var nanos: Long) : MonotonicTicker {
94+
override fun tickNanos(): Long = nanos
95+
96+
fun setNanos(value: Long) {
97+
nanos = value
98+
}
99+
}
100+
85101
private val fixture = Fixture()
86102

87103
@Test

‎sentry-android-sqlite/src/main/java/io/sentry/sqlite/DriverSpans.kt‎

Lines changed: 7 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -4,29 +4,21 @@ import io.sentry.IScopes
44
import io.sentry.ISpan
55
import io.sentry.Instrumenter
66
import io.sentry.ScopesAdapter
7-
import io.sentry.SentryDate
87
import io.sentry.SentryLongDate
9-
import io.sentry.SentryNanotimeDate
108
import io.sentry.SentryStackTraceFactory
119
import io.sentry.SpanDataConvention
1210
import io.sentry.SpanStatus
1311

1412
private const val SQLITE_TRACE_ORIGIN = "auto.db.sqlite"
1513

16-
/**
17-
* Sentinel for extracting a [SentryNanotimeDate]'s underlying [System.nanoTime] value via
18-
* [SentryDate.diff].
19-
*/
20-
private val EMPTY_NANO_TIME = SentryNanotimeDate(0, 0L)
21-
2214
/** Span instrumentation for [SentrySQLiteDriver]. */
2315
internal class DriverSpans(private val scopes: IScopes, private val dbMetadata: DbMetadata) {
2416

2517
private val stackTraceFactory = SentryStackTraceFactory(scopes.options)
2618

2719
/**
2820
* Returns a timestamp in nanoseconds for use with [record]. Timestamp is ns-precise if the active
29-
* parent span uses a [SentryNanotimeDate] (the ordinary case); otherwise it's ms-precise.
21+
* parent span is anchored (the ordinary case); otherwise it's ms-precise.
3022
*
3123
* Note: Internalizing the start time in [record] would shift spans to end-of-work on the trace
3224
* timeline, which is less desirable; callers capture the start before doing database work and
@@ -104,14 +96,9 @@ internal class DriverSpans(private val scopes: IScopes, private val dbMetadata:
10496
* END TRANSACTION ├███┤ 0.33 ms
10597
* ```
10698
*/
107-
internal fun ISpan.computeNanoStartTimestampForChild(): Long? {
108-
if (startDate !is SentryNanotimeDate) {
109-
return null
110-
}
111-
112-
val parentWallClockNanos = startDate.nanoTimestamp()
113-
val parentMonotonicNanos = startDate.diff(EMPTY_NANO_TIME)
114-
val elapsedSinceParentStart = System.nanoTime() - parentMonotonicNanos
115-
// Return the child's absolute start time.
116-
return parentWallClockNanos + elapsedSinceParentStart
117-
}
99+
internal fun ISpan.computeNanoStartTimestampForChild(): Long? =
100+
// An anchored span projects nanosecond instants from the transaction's single wall-clock
101+
// reading, so "now" on its own timeline is exactly where a child span should start. No
102+
// reconstruction, and no silent drop to millisecond precision when the parent's date happens
103+
// not to be anchored.
104+
anchor()?.now()?.epochNanos()

0 commit comments

Comments
 (0)