From d29d3f8dd4e93ab97ec8e33d43b5f1998df8a87d Mon Sep 17 00:00:00 2001 From: Adam Brown Date: Fri, 12 Jun 2026 12:07:15 +0200 Subject: [PATCH] chore(android-sqlite): Repair start times of spans generated by SentrySQLiteDriver (JAVA-275) Repairs the nanoTimetamp of the SentryNanotimeDates used as start times for the spans generated by SentrySQLiteDriver. Without those repairs, all spans within a given wall clock millisecond are displayed by Sentry UI as starting at that same millisecond and are re-ordered arbitrarily. Often that's quite confusing as actual BEGIN -> EXECUTE STATEMENT -> END sequences can appear as EXECUTE STATEMENT -> END -> BEGIN (etc.). For more details, see the discussion [here](https://github.com/getsentry/sentry-java/pull/5504#issuecomment-4679631245). --- .../android/sqlite/SQLiteSpanManager.kt | 4 +- .../sqlite/SQLiteSpanInstrumentation.kt | 60 +++- .../sqlite/SQLiteSpanInstrumentationTest.kt | 279 +++++++++++++++++- 3 files changed, 325 insertions(+), 18 deletions(-) diff --git a/sentry-android-sqlite/src/main/java/io/sentry/android/sqlite/SQLiteSpanManager.kt b/sentry-android-sqlite/src/main/java/io/sentry/android/sqlite/SQLiteSpanManager.kt index 3495d3a71f..bed16fb57a 100644 --- a/sentry-android-sqlite/src/main/java/io/sentry/android/sqlite/SQLiteSpanManager.kt +++ b/sentry-android-sqlite/src/main/java/io/sentry/android/sqlite/SQLiteSpanManager.kt @@ -41,10 +41,10 @@ internal class SQLiteSpanManager( if (result is CrossProcessCursor) { return SentryCrossProcessCursor(result, this, sql) as T } - spans.recordSpan(sql, startTimestamp, SpanStatus.OK) + spans.recordCoarseSpan(sql, startTimestamp, SpanStatus.OK) result } catch (e: Throwable) { - spans.recordSpan(sql, startTimestamp, SpanStatus.INTERNAL_ERROR, e) + spans.recordCoarseSpan(sql, startTimestamp, SpanStatus.INTERNAL_ERROR, e) throw e } } diff --git a/sentry-android-sqlite/src/main/java/io/sentry/sqlite/SQLiteSpanInstrumentation.kt b/sentry-android-sqlite/src/main/java/io/sentry/sqlite/SQLiteSpanInstrumentation.kt index 53df4de921..8cf7bcb6da 100644 --- a/sentry-android-sqlite/src/main/java/io/sentry/sqlite/SQLiteSpanInstrumentation.kt +++ b/sentry-android-sqlite/src/main/java/io/sentry/sqlite/SQLiteSpanInstrumentation.kt @@ -1,10 +1,12 @@ package io.sentry.sqlite import io.sentry.IScopes +import io.sentry.ISpan import io.sentry.Instrumenter import io.sentry.ScopesAdapter import io.sentry.SentryDate import io.sentry.SentryLongDate +import io.sentry.SentryNanotimeDate import io.sentry.SentryStackTraceFactory import io.sentry.SpanDataConvention import io.sentry.SpanStatus @@ -28,36 +30,44 @@ internal class SQLiteSpanInstrumentation( */ fun startTimestamp(): SentryDate = scopes.options.dateProvider.now() - /** Records a `db.sql.query` span from [startTimestamp] to the moment of invocation. */ + /** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */ fun recordSpan( sql: String, startTimestamp: SentryDate, + durationNanos: Long, status: SpanStatus, throwable: Throwable? = null, ) { - recordSpan(sql, startTimestamp, endTimestamp = null, status, throwable) + val parent = scopes.span ?: return + val nanoPrecisionStart = startTimestamp.repairPrecision(baseline = parent.startDate) + val endTimestamp = SentryLongDate(nanoPrecisionStart.nanoTimestamp() + durationNanos) + parent.recordChild(sql, nanoPrecisionStart, endTimestamp, status, throwable) } - /** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */ - fun recordSpan( + /** + * Records a `db.sql.query` span from [startTimestamp] to the moment of invocation. + * + * "Coarse" in that it doesn't ensure nanosecond precision for [SentryNanotimeDate] + * [startTimestamp]s. + */ + fun recordCoarseSpan( sql: String, startTimestamp: SentryDate, - durationNanos: Long, status: SpanStatus, throwable: Throwable? = null, ) { - val endTimestamp = SentryLongDate(startTimestamp.nanoTimestamp() + durationNanos) - recordSpan(sql, startTimestamp, endTimestamp, status, throwable) + val parent = scopes.span ?: return + parent.recordChild(sql, startTimestamp, endTimestamp = null, status, throwable) } - private fun recordSpan( + private fun ISpan.recordChild( sql: String, startTimestamp: SentryDate, endTimestamp: SentryDate?, status: SpanStatus, throwable: Throwable?, ) { - scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)?.apply { + startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY).apply { spanContext.origin = SQLITE_TRACE_ORIGIN throwable?.let { this.throwable = it } @@ -74,6 +84,38 @@ internal class SQLiteSpanInstrumentation( } } + /** + * Repairs the receiver's [nanoTimestamp][SentryDate.nanoTimestamp] if needed so that it actually + * has nanosecond precision. + * + * Designed for use with spans whose start timestamps are [SentryNanotimeDate]s. Without repair, + * those timestamps will be aligned to the same millisecond at transport, and the Sentry UI will + * arbitrarily reorder them: + * ``` + * Parent span ├█████████████┤ + * END TRANSACTION ├███┤ 0.18 ms ← (Wrong order) + * BEGIN IMMEDIATE TRANSACTION ├████┤ 0.25 ms + * INSERT INTO `my_db` … ├██┤ 0.10 ms + * ↑ + * (All spans share the same ms baseline + * even though their execution was staggered) + * ``` + * + * Repair ensures proper ordering and lets the spans stagger: + * ``` + * Parent span ├█████████████┤ + * BEGIN IMMEDIATE TRANSACTION ├████┤ 0.25 ms + * INSERT INTO `my_db` … ├██┤ 0.10 ms + * END TRANSACTION ├███┤ 0.18 ms + * ``` + */ + private fun SentryDate.repairPrecision(baseline: SentryDate?): SentryDate = + if (baseline is SentryNanotimeDate) { + SentryLongDate(baseline.laterDateNanosTimestampByDiff(this)) + } else { + this + } + companion object { fun fromDatabaseName(databaseName: String?, scopes: IScopes = ScopesAdapter.getInstance()) = diff --git a/sentry-android-sqlite/src/test/java/io/sentry/sqlite/SQLiteSpanInstrumentationTest.kt b/sentry-android-sqlite/src/test/java/io/sentry/sqlite/SQLiteSpanInstrumentationTest.kt index ead123a190..c60446c2da 100644 --- a/sentry-android-sqlite/src/test/java/io/sentry/sqlite/SQLiteSpanInstrumentationTest.kt +++ b/sentry-android-sqlite/src/test/java/io/sentry/sqlite/SQLiteSpanInstrumentationTest.kt @@ -1,12 +1,15 @@ package io.sentry.sqlite import io.sentry.IScopes +import io.sentry.SentryDateProvider +import io.sentry.SentryNanotimeDate import io.sentry.SentryOptions import io.sentry.SentryTracer import io.sentry.SpanDataConvention import io.sentry.SpanStatus import io.sentry.TransactionContext import io.sentry.util.thread.IThreadChecker +import java.util.Date import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFalse @@ -79,7 +82,6 @@ class SQLiteSpanInstrumentationTest { sut.recordSpan("SELECT 1", start, durationNanos, SpanStatus.OK) val span = fixture.sentryTracer.children.first() - assertEquals(start, span.startDate) assertEquals(span.startDate.nanoTimestamp() + durationNanos, span.finishDate!!.nanoTimestamp()) } @@ -147,11 +149,130 @@ class SQLiteSpanInstrumentationTest { } @Test - fun `recordSpan without a duration finishes the span at the time of invocation`() { + fun `recordSpan repairs start precision when parent uses SentryNanotimeDate`() { + val sameMillis = Date(1_000_000L) + val parentNanos = 100_000_000L + val childNanos = 100_500_000L + + val sut = + setUpWithNanotimeDates( + SentryNanotimeDate(sameMillis, parentNanos), + SentryNanotimeDate(sameMillis, childNanos), + ) + val start = sut.startTimestamp() + val durationNanos = 42_000_000L + + sut.recordSpan("SELECT 1", start, durationNanos, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + + val parentStart = fixture.sentryTracer.startDate + val expectedStart = parentStart.laterDateNanosTimestampByDiff(start) + assertEquals(expectedStart, span.startDate.nanoTimestamp()) + assertEquals(expectedStart + durationNanos, span.finishDate!!.nanoTimestamp()) + } + + @Test + fun `recordSpan gives distinct ordered starts within the same millisecond`() { + val sameMillis = Date(1_000_000L) + val parentNanos = 100_000_000L + val child1Nanos = 100_200_000L + val child2Nanos = 100_800_000L + + val sut = + setUpWithNanotimeDates( + SentryNanotimeDate(sameMillis, parentNanos), + SentryNanotimeDate(sameMillis, child1Nanos), + SentryNanotimeDate(sameMillis, child2Nanos), + ) + val start1 = sut.startTimestamp() + val start2 = sut.startTimestamp() + + assertEquals( + start1.nanoTimestamp(), + start2.nanoTimestamp(), + "Raw starts share the same ms-quantized timestamp", + ) + + sut.recordSpan("SELECT 1", start1, 1_000_000, SpanStatus.OK) + sut.recordSpan("SELECT 2", start2, 1_000_000, SpanStatus.OK) + + val span1 = fixture.sentryTracer.children[0] + val span2 = fixture.sentryTracer.children[1] + + assertTrue( + span1.startDate.nanoTimestamp() < span2.startDate.nanoTimestamp(), + "Repaired starts should be distinct and ordered", + ) + } + + @Test + fun `recordSpan preserves exact duration after precision repair`() { + val sameMillis = Date(1_000_000L) + val sut = + setUpWithNanotimeDates( + SentryNanotimeDate(sameMillis, 100_000_000L), + SentryNanotimeDate(sameMillis, 100_750_000L), + ) + val start = sut.startTimestamp() + val durationNanos = 123_456L + + sut.recordSpan("SELECT 1", start, durationNanos, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + val actualDuration = span.finishDate!!.nanoTimestamp() - span.startDate.nanoTimestamp() + assertEquals(durationNanos, actualDuration) + } + + @Test + fun `recordSpan does not repair start when parent is not SentryNanotimeDate`() { + val sut = fixture.getSut(isTransactionActive = true) + val start = sut.startTimestamp() + val durationNanos = 1_000_000L + + sut.recordSpan("SELECT 1", start, durationNanos, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals(start.nanoTimestamp(), span.startDate.nanoTimestamp()) + assertEquals(start.nanoTimestamp() + durationNanos, span.finishDate!!.nanoTimestamp()) + } + + @Test + fun `recordCoarseSpan records a span if a transaction is active`() { + val sut = fixture.getSut(isTransactionActive = true) + sut.recordCoarseSpan("SELECT 1", sut.startTimestamp(), SpanStatus.OK) + assertEquals(1, fixture.sentryTracer.children.size) + } + + @Test + fun `recordCoarseSpan does not record a span if no transaction is active`() { + val sut = fixture.getSut(isTransactionActive = false) + val start = sut.startTimestamp() + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) + assertEquals(0, fixture.sentryTracer.children.size) + } + + @Test + fun `recordCoarseSpan creates a span with correct properties`() { val sut = fixture.getSut() val start = sut.startTimestamp() + sut.recordCoarseSpan("SELECT * FROM users", start, SpanStatus.OK) - sut.recordSpan("SELECT 1", start, SpanStatus.OK) + val span = fixture.sentryTracer.children.firstOrNull() + assertNotNull(span) + assertEquals("db.sql.query", span.operation) + assertEquals("SELECT * FROM users", span.description) + assertEquals("auto.db.sqlite", span.spanContext.origin) + assertEquals(SpanStatus.OK, span.status) + assertTrue(span.isFinished) + } + + @Test + fun `recordCoarseSpan finishes the span at the time of invocation`() { + val sut = fixture.getSut() + val start = sut.startTimestamp() + + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) val span = fixture.sentryTracer.children.first() assertTrue(span.isFinished) @@ -162,14 +283,144 @@ class SQLiteSpanInstrumentationTest { } @Test - fun `fromFileName sets db name from fileName`() { + fun `recordCoarseSpan attaches throwable when provided`() { + val sut = fixture.getSut() + val start = sut.startTimestamp() + val exception = RuntimeException("disk I/O error") + + sut.recordCoarseSpan("INSERT INTO t VALUES(1)", start, SpanStatus.INTERNAL_ERROR, exception) + + val span = fixture.sentryTracer.children.first() + assertEquals(SpanStatus.INTERNAL_ERROR, span.status) + assertEquals(exception, span.throwable) + } + + @Test + fun `recordCoarseSpan sets db system and db name when fileName is not the in-memory sentinel`() { + val sut = fixture.getSut(fileName = "/data/data/com.example/databases/tracks.db") + val start = sut.startTimestamp() + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals("sqlite", span.data[SpanDataConvention.DB_SYSTEM_KEY]) + assertEquals("tracks.db", span.data[SpanDataConvention.DB_NAME_KEY]) + } + + @Test + fun `recordCoarseSpan sets db system only when fileName is the in-memory sentinel`() { + val sut = fixture.getSut(fileName = ":memory:") + val start = sut.startTimestamp() + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals("in-memory", span.data[SpanDataConvention.DB_SYSTEM_KEY]) + assertNull(span.data[SpanDataConvention.DB_NAME_KEY]) + } + + @Test + fun `recordCoarseSpan sets blocked_main_thread to true and attaches call stack on main thread`() { + val sut = fixture.getSut() + fixture.options.threadChecker = mock() + whenever(fixture.options.threadChecker.isMainThread).thenReturn(true) + whenever(fixture.options.threadChecker.currentThreadName).thenReturn("main") + + sut.recordCoarseSpan("SELECT 1", sut.startTimestamp(), SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertTrue(span.getData(SpanDataConvention.BLOCKED_MAIN_THREAD_KEY) as Boolean) + assertNotNull(span.getData(SpanDataConvention.CALL_STACK_KEY)) + } + + @Test + fun `recordCoarseSpan sets blocked_main_thread to false and does not attach a call stack on background thread`() { + val sut = fixture.getSut() + fixture.options.threadChecker = mock() + whenever(fixture.options.threadChecker.isMainThread).thenReturn(false) + whenever(fixture.options.threadChecker.currentThreadName).thenReturn("worker") + + sut.recordCoarseSpan("SELECT 1", sut.startTimestamp(), SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertFalse(span.getData(SpanDataConvention.BLOCKED_MAIN_THREAD_KEY) as Boolean) + assertNull(span.getData(SpanDataConvention.CALL_STACK_KEY)) + } + + @Test + fun `recordCoarseSpan does not repair start precision when parent uses SentryNanotimeDate`() { + val sameMillis = Date(1_000_000L) + val parentNanos = 100_000_000L + val childNanos = 100_500_000L + + val finishNanos = 100_900_000L + val sut = + setUpWithNanotimeDates( + SentryNanotimeDate(sameMillis, parentNanos), + SentryNanotimeDate(sameMillis, childNanos), + SentryNanotimeDate(sameMillis, finishNanos), + ) + val start = sut.startTimestamp() + + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals(start.nanoTimestamp(), span.startDate.nanoTimestamp()) + assertTrue(span.finishDate!!.nanoTimestamp() >= span.startDate.nanoTimestamp()) + } + + @Test + fun `recordCoarseSpan does not repair start when parent is not SentryNanotimeDate`() { + val sut = fixture.getSut(isTransactionActive = true) + val start = sut.startTimestamp() + + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals(start.nanoTimestamp(), span.startDate.nanoTimestamp()) + assertTrue(span.finishDate!!.nanoTimestamp() >= start.nanoTimestamp()) + } + + @Test + fun `fromFileName sets db name from fileName when using recordSpan`() { + val options = SentryOptions().apply { dsn = "https://key@sentry.io/proj" } + whenever(fixture.scopes.options).thenReturn(options) + fixture.sentryTracer = SentryTracer(TransactionContext("name", "op"), fixture.scopes) + whenever(fixture.scopes.span).thenReturn(fixture.sentryTracer) + + val sut = SQLiteSpanInstrumentation.fromFileName("tracks.db", fixture.scopes) + val start = sut.startTimestamp() + sut.recordSpan("SELECT 1", start, 1_000_000, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals("sqlite", span.data[SpanDataConvention.DB_SYSTEM_KEY]) + assertEquals("tracks.db", span.data[SpanDataConvention.DB_NAME_KEY]) + } + + @Test + fun `fromDatabaseName sets db name from databaseName when using recordSpan`() { + val options = SentryOptions().apply { dsn = "https://key@sentry.io/proj" } + whenever(fixture.scopes.options).thenReturn(options) + fixture.sentryTracer = SentryTracer(TransactionContext("name", "op"), fixture.scopes) + whenever(fixture.scopes.span).thenReturn(fixture.sentryTracer) + + val sut = SQLiteSpanInstrumentation.fromDatabaseName("tracks.db", fixture.scopes) + val start = sut.startTimestamp() + sut.recordSpan("SELECT 1", start, 1_000_000, SpanStatus.OK) + + val span = fixture.sentryTracer.children.first() + assertEquals("sqlite", span.data[SpanDataConvention.DB_SYSTEM_KEY]) + assertEquals("tracks.db", span.data[SpanDataConvention.DB_NAME_KEY]) + } + + @Test + fun `fromFileName sets db name from fileName when using recordCoarseSpan`() { val options = SentryOptions().apply { dsn = "https://key@sentry.io/proj" } whenever(fixture.scopes.options).thenReturn(options) fixture.sentryTracer = SentryTracer(TransactionContext("name", "op"), fixture.scopes) whenever(fixture.scopes.span).thenReturn(fixture.sentryTracer) val sut = SQLiteSpanInstrumentation.fromFileName("tracks.db", fixture.scopes) - sut.recordSpan("SELECT 1", sut.startTimestamp(), SpanStatus.OK) + val start = sut.startTimestamp() + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) val span = fixture.sentryTracer.children.first() assertEquals("sqlite", span.data[SpanDataConvention.DB_SYSTEM_KEY]) @@ -177,17 +428,31 @@ class SQLiteSpanInstrumentationTest { } @Test - fun `fromDatabaseName sets db name from databaseName`() { + fun `fromDatabaseName sets db name from databaseName when using recordCoarseSpan`() { val options = SentryOptions().apply { dsn = "https://key@sentry.io/proj" } whenever(fixture.scopes.options).thenReturn(options) fixture.sentryTracer = SentryTracer(TransactionContext("name", "op"), fixture.scopes) whenever(fixture.scopes.span).thenReturn(fixture.sentryTracer) val sut = SQLiteSpanInstrumentation.fromDatabaseName("tracks.db", fixture.scopes) - sut.recordSpan("SELECT 1", sut.startTimestamp(), SpanStatus.OK) + val start = sut.startTimestamp() + sut.recordCoarseSpan("SELECT 1", start, SpanStatus.OK) val span = fixture.sentryTracer.children.first() assertEquals("sqlite", span.data[SpanDataConvention.DB_SYSTEM_KEY]) assertEquals("tracks.db", span.data[SpanDataConvention.DB_NAME_KEY]) } + + private fun setUpWithNanotimeDates(vararg dates: SentryNanotimeDate): SQLiteSpanInstrumentation { + val dateQueue = ArrayDeque(dates.toList()) + val options = + SentryOptions().apply { + dsn = "https://key@sentry.io/proj" + dateProvider = SentryDateProvider { dateQueue.removeFirst() } + } + whenever(fixture.scopes.options).thenReturn(options) + fixture.sentryTracer = SentryTracer(TransactionContext("name", "op"), fixture.scopes) + whenever(fixture.scopes.span).thenReturn(fixture.sentryTracer) + return SQLiteSpanInstrumentation.fromFileName(":memory:", fixture.scopes) + } }