chore(android-sqlite): Repair start times of spans generated by SentrySQLiteDriver (#5543)

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](#5504 (comment)).

Author: 0xadam-brown

sentry-android-sqlite/src/main/java/io/sentry/android/sqlite/SQLiteSpanManager.kt

@@ -3,17 +3,21 @@ package io.sentry.android.sqlite
 import android.database.CrossProcessCursor
 import android.database.SQLException
 import io.sentry.IScopes
+import io.sentry.ISpan
+import io.sentry.Instrumenter
 import io.sentry.ScopesAdapter
 import io.sentry.SentryIntegrationPackageStorage
+import io.sentry.SentryStackTraceFactory
+import io.sentry.SpanDataConvention
 import io.sentry.SpanStatus
-import io.sentry.sqlite.SQLiteSpanInstrumentation
+
+private const val TRACE_ORIGIN = "auto.db.sqlite"
 
 internal class SQLiteSpanManager(
   private val scopes: IScopes = ScopesAdapter.getInstance(),
-  databaseName: String? = null,
+  private val databaseName: String? = null,
 ) {
-
-  private val spans = SQLiteSpanInstrumentation.fromDatabaseName(databaseName, scopes)
+  private val stackTraceFactory = SentryStackTraceFactory(scopes.options)
 
   init {
     SentryIntegrationPackageStorage.getInstance().addIntegration("SQLite")
@@ -29,8 +33,8 @@ internal class SQLiteSpanManager(
   @Suppress("TooGenericExceptionCaught", "UNCHECKED_CAST")
   @Throws(SQLException::class)
   fun <T> performSql(sql: String, operation: () -> T): T {
-    val startTimestamp = spans.startTimestamp()
-
+    val startTimestamp = scopes.getOptions().dateProvider.now()
+    var span: ISpan? = null
     return try {
       val result = operation()
       /*
@@ -41,11 +45,34 @@ internal class SQLiteSpanManager(
       if (result is CrossProcessCursor) {
         return SentryCrossProcessCursor(result, this, sql) as T
       }
-      spans.recordSpan(sql, startTimestamp, SpanStatus.OK)
+      span = scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)
+      span?.spanContext?.origin = TRACE_ORIGIN
+      span?.status = SpanStatus.OK
       result
     } catch (e: Throwable) {
-      spans.recordSpan(sql, startTimestamp, SpanStatus.INTERNAL_ERROR, e)
+      span = scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)
+      span?.spanContext?.origin = TRACE_ORIGIN
+      span?.status = SpanStatus.INTERNAL_ERROR
+      span?.throwable = e
       throw e
+    } finally {
+      span?.apply {
+        val isMainThread: Boolean = scopes.options.threadChecker.isMainThread
+        setData(SpanDataConvention.BLOCKED_MAIN_THREAD_KEY, isMainThread)
+        if (isMainThread) {
+          setData(SpanDataConvention.CALL_STACK_KEY, stackTraceFactory.inAppCallStack)
+        }
+        // if db name is null, then it's an in-memory database as per
+        // https://cs.android.com/androidx/platform/frameworks/support/+/androidx-main:sqlite/sqlite/src/main/java/androidx/sqlite/db/SupportSQLiteOpenHelper.kt;l=38-42
+        if (databaseName != null) {
+          setData(SpanDataConvention.DB_SYSTEM_KEY, "sqlite")
+          setData(SpanDataConvention.DB_NAME_KEY, databaseName)
+        } else {
+          setData(SpanDataConvention.DB_SYSTEM_KEY, "in-memory")
+        }
+
+        finish()
+      }
     }
   }
 }

sentry-android-sqlite/src/main/java/io/sentry/sqlite/DbMetadata.kt

@@ -36,14 +36,3 @@ internal fun dbMetadataFromFileName(fileName: String): DbMetadata {
   val basename = if (index >= 0) trimmed.substring(index + 1) else trimmed
   return DbMetadata(name = basename.ifEmpty { null }, system = DB_SYSTEM_SQLITE)
 }
-
-/**
- * Returns metadata based on
- * [SupportSQLiteOpenHelper.databaseName][androidx.sqlite.db.SupportSQLiteOpenHelper.databaseName].
- */
-internal fun dbMetadataFromDatabaseName(databaseName: String?): DbMetadata =
-  if (databaseName == null) {
-    DbMetadata(name = null, system = DB_SYSTEM_IN_MEMORY)
-  } else {
-    DbMetadata(name = databaseName, system = DB_SYSTEM_SQLITE)
-  }

sentry-android-sqlite/src/main/java/io/sentry/sqlite/SQLiteSpanInstrumentation.kt

@@ -1,17 +1,26 @@
 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
+import java.util.Date
 
 private const val SQLITE_TRACE_ORIGIN = "auto.db.sqlite"
 
-/** Shared span instrumentation for SQLite. */
+/**
+ * Sentinel for extracting a [SentryNanotimeDate]'s underlying [System.nanoTime] value via
+ * [SentryDate.diff].
+ */
+private val EMPTY_NANO_TIME = SentryNanotimeDate(Date(0), 0L)
+
+/** Span instrumentation for [SentrySQLiteDriver]. */
 internal class SQLiteSpanInstrumentation(
   private val scopes: IScopes,
   private val dbMetadata: DbMetadata,
@@ -20,44 +29,32 @@ internal class SQLiteSpanInstrumentation(
   private val stackTraceFactory = SentryStackTraceFactory(scopes.options)
 
   /**
-   * Returns a start timestamp for a `db.sql.query` span.
+   * Returns a timestamp in nanoseconds for use with [recordSpan]. Timestamp is ns-precise if the
+   * active parent span uses a [SentryNanotimeDate] (the ordinary case); otherwise it's ms-precise.
    *
-   * Exposed so callers can capture a wall-clock start before accumulating database time.
-   * Internalizing the start time in [recordSpan] would shift spans to end-of-work on the trace
-   * timeline, which is less desirable.
+   * Note: Internalizing the start time in [recordSpan] would shift spans to end-of-work on the
+   * trace timeline, which is less desirable; callers capture the start before doing database work
+   * and pass it back to [recordSpan].
    */
-  fun startTimestamp(): SentryDate = scopes.options.dateProvider.now()
-
-  /** Records a `db.sql.query` span from [startTimestamp] to the moment of invocation. */
-  fun recordSpan(
-    sql: String,
-    startTimestamp: SentryDate,
-    status: SpanStatus,
-    throwable: Throwable? = null,
-  ) {
-    recordSpan(sql, startTimestamp, endTimestamp = null, status, throwable)
-  }
+  fun startTimestamp(): Long =
+    // Try to retain nanosecond precision + avoid SentryDate allocation...
+    scopes.span?.computeNanoStartTimestampForChild()
+      // ...otherwise fall back to millisecond precision + allocate.
+      ?: scopes.options.dateProvider.now().nanoTimestamp()
 
-  /** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */
+  /** Records a `db.sql.query` span. */
   fun recordSpan(
     sql: String,
-    startTimestamp: SentryDate,
+    startTimestampNanos: Long,
     durationNanos: Long,
     status: SpanStatus,
     throwable: Throwable? = null,
   ) {
-    val endTimestamp = SentryLongDate(startTimestamp.nanoTimestamp() + durationNanos)
-    recordSpan(sql, startTimestamp, endTimestamp, status, throwable)
-  }
+    val parent = scopes.span ?: return
+    val startTimestamp = SentryLongDate(startTimestampNanos)
+    val endTimestamp = SentryLongDate(startTimestampNanos + durationNanos)
 
-  private fun recordSpan(
-    sql: String,
-    startTimestamp: SentryDate,
-    endTimestamp: SentryDate?,
-    status: SpanStatus,
-    throwable: Throwable?,
-  ) {
-    scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)?.apply {
+    parent.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY).apply {
       spanContext.origin = SQLITE_TRACE_ORIGIN
       throwable?.let { this.throwable = it }
 
@@ -85,15 +82,43 @@ internal class SQLiteSpanInstrumentation(
       scopes: IScopes = ScopesAdapter.getInstance(),
     ): SQLiteSpanInstrumentation =
       SQLiteSpanInstrumentation(scopes, dbMetadataFromFileName(fileName))
+  }
+}
 
-    /**
-     * Returns [SQLiteSpanInstrumentation] based on
-     * [SupportSQLiteOpenHelper.databaseName][androidx.sqlite.db.SupportSQLiteOpenHelper.databaseName].
-     */
-    fun fromDatabaseName(
-      databaseName: String?,
-      scopes: IScopes = ScopesAdapter.getInstance(),
-    ): SQLiteSpanInstrumentation =
-      SQLiteSpanInstrumentation(scopes, dbMetadataFromDatabaseName(databaseName))
+/**
+ * Computes a start timestamp with nanosecond precision for the child of the receiver span. Returns
+ * null if nanosecond precision isn't possible.
+ *
+ * Lets us improve the display of spans in the Sentry UI. If timestamps are only ms-precise, the
+ * Sentry UI will left-align and arbitrarily reorder spans that share the same wall clock ms:
+ * ```
+ *                                  (Relative start times out of order)
+ *                                                ↓
+ * Parent span                 ├█████████████┤
+ * END TRANSACTION              ├███┤          0.33 ms
+ * BEGIN IMMEDIATE TRANSACTION  ├████┤         0.02 ms
+ * INSERT INTO `my_db` …        ├██┤           0.30 ms
+ *                              ↑
+ *               (All spans share the same ms baseline
+ *             even though their execution was staggered)
+ * ```
+ *
+ * Nanosecond precision ensures proper ordering and lets the spans stagger:
+ * ```
+ * Parent span                 ├█████████████┤
+ * BEGIN IMMEDIATE TRANSACTION  ├████┤         0.02 ms
+ * INSERT INTO `my_db` …              ├██┤     0.30 ms
+ * END TRANSACTION                     ├███┤   0.33 ms
+ * ```
+ */
+internal fun ISpan.computeNanoStartTimestampForChild(): Long? {
+  if (startDate !is SentryNanotimeDate) {
+    return null
   }
+
+  val parentWallClockNanos = startDate.nanoTimestamp()
+  val parentMonotonicNanos = startDate.diff(EMPTY_NANO_TIME)
+  val elapsedSinceParentStart = System.nanoTime() - parentMonotonicNanos
+  // Return the child's absolute start time.
+  return parentWallClockNanos + elapsedSinceParentStart
 }

sentry-android-sqlite/src/main/java/io/sentry/sqlite/SentrySQLiteStatement.kt

@@ -1,7 +1,6 @@
 package io.sentry.sqlite
 
 import androidx.sqlite.SQLiteStatement
-import io.sentry.SentryDate
 import io.sentry.SpanStatus
 
 /**
@@ -22,7 +21,7 @@ internal class SentrySQLiteStatement(
   private val nanoTimeProvider: () -> Long = { System.nanoTime() },
 ) : SQLiteStatement by delegate {
 
-  private var firstStepTimestamp: SentryDate? = null
+  private var firstStepTimestampNanos: Long? = null
   private var accumulatedDbNanos: Long = 0L
   private var stepsComplete = false
   private var closed = false
@@ -35,8 +34,8 @@ internal class SentrySQLiteStatement(
 
     val beforeNanos = nanoTimeProvider()
     return try {
-      if (firstStepTimestamp == null) {
-        firstStepTimestamp = spans.startTimestamp()
+      if (firstStepTimestampNanos == null) {
+        firstStepTimestampNanos = spans.startTimestamp()
       }
 
       stepsComplete = !delegate.step()
@@ -71,10 +70,10 @@ internal class SentrySQLiteStatement(
   }
 
   private fun recordSpan(status: SpanStatus, throwable: Throwable? = null) {
-    val start = firstStepTimestamp ?: return
+    val startNanos = firstStepTimestampNanos ?: return
     val duration = accumulatedDbNanos
-    firstStepTimestamp = null
+    firstStepTimestampNanos = null
     accumulatedDbNanos = 0L
-    spans.recordSpan(sql, start, duration, status, throwable)
+    spans.recordSpan(sql, startNanos, duration, status, throwable)
   }
 }

sentry-android-sqlite/src/test/java/io/sentry/sqlite/ComputeNanoStartTimestampForChildTest.kt

@@ -0,0 +1,100 @@
+package io.sentry.sqlite
+
+import io.sentry.DateUtils
+import io.sentry.ISpan
+import io.sentry.SentryLongDate
+import io.sentry.SentryNanotimeDate
+import java.util.Date
+import kotlin.test.Test
+import kotlin.test.assertEquals
+import kotlin.test.assertNull
+import kotlin.test.assertTrue
+import org.mockito.kotlin.mock
+import org.mockito.kotlin.whenever
+
+class ComputeNanoStartTimestampForChildTest {
+
+  @Test
+  fun `returns parent wall clock plus elapsed monotonic time since parent started`() {
+    val wallClockMillis = 1_000_000L
+    val elapsedNanos = 500_000L
+    val parentMonotonicNanos = System.nanoTime() - elapsedNanos
+    val span = spanWithNanotimeStart(wallClockMillis, parentMonotonicNanos)
+
+    val timestamp = span.computeNanoStartTimestampForChild()!!
+
+    val elapsedSinceParentStart = timestamp - DateUtils.millisToNanos(wallClockMillis)
+    assertTrue(elapsedSinceParentStart >= elapsedNanos)
+    assertTrue(elapsedSinceParentStart < elapsedNanos + TEST_SLACK_NANOS)
+  }
+
+  @Test
+  fun `same millisecond wall clocks with different monotonic offsets produce distinct ordered timestamps`() {
+    val wallClockMillis = 1_000_000L
+    val wallClockNanos = DateUtils.millisToNanos(wallClockMillis)
+    val earlierParentMonotonicNanos = System.nanoTime() - 200_000L
+    val laterParentMonotonicNanos = System.nanoTime() - 800_000L
+    val earlierSpan = spanWithNanotimeStart(wallClockMillis, earlierParentMonotonicNanos)
+    val laterSpan = spanWithNanotimeStart(wallClockMillis, laterParentMonotonicNanos)
+
+    assertEquals(
+      earlierSpan.startDate.nanoTimestamp(),
+      laterSpan.startDate.nanoTimestamp(),
+      "Raw parent timestamps share the same ms-quantized value",
+    )
+
+    val earlier = earlierSpan.computeNanoStartTimestampForChild()!!
+    val later = laterSpan.computeNanoStartTimestampForChild()!!
+
+    assertTrue(earlier > wallClockNanos)
+    assertTrue(later > wallClockNanos)
+    assertTrue(earlier < later)
+    assertTrue(later - earlier >= 500_000L)
+  }
+
+  @Test
+  fun `returns parent wall clock when no monotonic time has elapsed since parent started`() {
+    val wallClockMillis = 1_000_000L
+    val parentMonotonicNanos = System.nanoTime()
+    val span = spanWithNanotimeStart(wallClockMillis, parentMonotonicNanos)
+
+    val elapsedSinceParentStart =
+      span.computeNanoStartTimestampForChild()!! - DateUtils.millisToNanos(wallClockMillis)
+    assertTrue(elapsedSinceParentStart >= 0L)
+    assertTrue(elapsedSinceParentStart < TEST_SLACK_NANOS)
+  }
+
+  @Test
+  fun `works when parent wall clock differs from millisecond baseline`() {
+    val wallClockMillis = 1_000_001L
+    val elapsedNanos = 1_500_000L
+    val parentMonotonicNanos = System.nanoTime() - elapsedNanos
+    val span = spanWithNanotimeStart(wallClockMillis, parentMonotonicNanos)
+
+    val elapsedSinceParentStart =
+      span.computeNanoStartTimestampForChild()!! - DateUtils.millisToNanos(wallClockMillis)
+    assertTrue(elapsedSinceParentStart >= elapsedNanos)
+    assertTrue(elapsedSinceParentStart < elapsedNanos + TEST_SLACK_NANOS)
+  }
+
+  @Test
+  fun `returns null when start date is not SentryNanotimeDate`() {
+    val span = mock<ISpan>()
+    whenever(span.startDate).thenReturn(SentryLongDate(DateUtils.millisToNanos(1_000_000L)))
+
+    assertNull(span.computeNanoStartTimestampForChild())
+  }
+
+  private fun spanWithNanotimeStart(wallClockMillis: Long, parentMonotonicNanos: Long): ISpan {
+    val startDate = SentryNanotimeDate(Date(wallClockMillis), parentMonotonicNanos)
+    val span = mock<ISpan>()
+    whenever(span.startDate).thenReturn(startDate)
+    return span
+  }
+
+  companion object {
+
+    // Upper bound for monotonic drift while the test body runs.
+    private const val TEST_SLACK_NANOS = 50_000_000L
+  }
+}

sentry-android-sqlite/src/test/java/io/sentry/sqlite/DbMetadataTest.kt

@@ -13,14 +13,6 @@ class DbMetadataTest {
     )
   }
 
-  @Test
-  fun `dbMetadataFromDatabaseName returns in-memory system with no db name when databaseName is null`() {
-    assertEquals(
-      DbMetadata(name = null, system = DB_SYSTEM_IN_MEMORY),
-      dbMetadataFromDatabaseName(null),
-    )
-  }
-
   @Test
   fun `dbMetadataFromFileName returns sqlite system and db name for unix path`() {
     assertEquals(