Skip to content

Commit 776deac

Browse files
committed
SQLiteSpanInstrumentation.startTimestamp() now returns Long + skips SentryDate allocation
1 parent 3eb3a3f commit 776deac

9 files changed

Lines changed: 240 additions & 410 deletions

File tree

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

Lines changed: 35 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -3,17 +3,21 @@ package io.sentry.android.sqlite
33
import android.database.CrossProcessCursor
44
import android.database.SQLException
55
import io.sentry.IScopes
6+
import io.sentry.ISpan
7+
import io.sentry.Instrumenter
68
import io.sentry.ScopesAdapter
79
import io.sentry.SentryIntegrationPackageStorage
10+
import io.sentry.SentryStackTraceFactory
11+
import io.sentry.SpanDataConvention
812
import io.sentry.SpanStatus
9-
import io.sentry.sqlite.SQLiteSpanInstrumentation
13+
14+
private const val TRACE_ORIGIN = "auto.db.sqlite"
1015

1116
internal class SQLiteSpanManager(
1217
private val scopes: IScopes = ScopesAdapter.getInstance(),
13-
databaseName: String? = null,
18+
private val databaseName: String? = null,
1419
) {
15-
16-
private val spans = SQLiteSpanInstrumentation.fromDatabaseName(databaseName, scopes)
20+
private val stackTraceFactory = SentryStackTraceFactory(scopes.options)
1721

1822
init {
1923
SentryIntegrationPackageStorage.getInstance().addIntegration("SQLite")
@@ -29,8 +33,8 @@ internal class SQLiteSpanManager(
2933
@Suppress("TooGenericExceptionCaught", "UNCHECKED_CAST")
3034
@Throws(SQLException::class)
3135
fun <T> performSql(sql: String, operation: () -> T): T {
32-
val startTimestamp = spans.startTimestamp()
33-
36+
val startTimestamp = scopes.getOptions().dateProvider.now()
37+
var span: ISpan? = null
3438
return try {
3539
val result = operation()
3640
/*
@@ -41,11 +45,34 @@ internal class SQLiteSpanManager(
4145
if (result is CrossProcessCursor) {
4246
return SentryCrossProcessCursor(result, this, sql) as T
4347
}
44-
spans.recordCoarseSpan(sql, startTimestamp, SpanStatus.OK)
48+
span = scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)
49+
span?.spanContext?.origin = TRACE_ORIGIN
50+
span?.status = SpanStatus.OK
4551
result
4652
} catch (e: Throwable) {
47-
spans.recordCoarseSpan(sql, startTimestamp, SpanStatus.INTERNAL_ERROR, e)
53+
span = scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)
54+
span?.spanContext?.origin = TRACE_ORIGIN
55+
span?.status = SpanStatus.INTERNAL_ERROR
56+
span?.throwable = e
4857
throw e
58+
} finally {
59+
span?.apply {
60+
val isMainThread: Boolean = scopes.options.threadChecker.isMainThread
61+
setData(SpanDataConvention.BLOCKED_MAIN_THREAD_KEY, isMainThread)
62+
if (isMainThread) {
63+
setData(SpanDataConvention.CALL_STACK_KEY, stackTraceFactory.inAppCallStack)
64+
}
65+
// if db name is null, then it's an in-memory database as per
66+
// https://cs.android.com/androidx/platform/frameworks/support/+/androidx-main:sqlite/sqlite/src/main/java/androidx/sqlite/db/SupportSQLiteOpenHelper.kt;l=38-42
67+
if (databaseName != null) {
68+
setData(SpanDataConvention.DB_SYSTEM_KEY, "sqlite")
69+
setData(SpanDataConvention.DB_NAME_KEY, databaseName)
70+
} else {
71+
setData(SpanDataConvention.DB_SYSTEM_KEY, "in-memory")
72+
}
73+
74+
finish()
75+
}
4976
}
5077
}
5178
}

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

Lines changed: 0 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -36,14 +36,3 @@ internal fun dbMetadataFromFileName(fileName: String): DbMetadata {
3636
val basename = if (index >= 0) trimmed.substring(index + 1) else trimmed
3737
return DbMetadata(name = basename.ifEmpty { null }, system = DB_SYSTEM_SQLITE)
3838
}
39-
40-
/**
41-
* Returns metadata based on
42-
* [SupportSQLiteOpenHelper.databaseName][androidx.sqlite.db.SupportSQLiteOpenHelper.databaseName].
43-
*/
44-
internal fun dbMetadataFromDatabaseName(databaseName: String?): DbMetadata =
45-
if (databaseName == null) {
46-
DbMetadata(name = null, system = DB_SYSTEM_IN_MEMORY)
47-
} else {
48-
DbMetadata(name = databaseName, system = DB_SYSTEM_SQLITE)
49-
}

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

Lines changed: 38 additions & 60 deletions
Original file line numberDiff line numberDiff line change
@@ -10,10 +10,17 @@ import io.sentry.SentryNanotimeDate
1010
import io.sentry.SentryStackTraceFactory
1111
import io.sentry.SpanDataConvention
1212
import io.sentry.SpanStatus
13+
import java.util.Date
1314

1415
private const val SQLITE_TRACE_ORIGIN = "auto.db.sqlite"
1516

16-
/** Shared span instrumentation for SQLite. */
17+
/**
18+
* Sentinel for extracting a [SentryNanotimeDate]'s underlying [System.nanoTime] value via
19+
* [SentryDate.diff].
20+
*/
21+
private val EMPTY_NANO_TIME = SentryNanotimeDate(Date(0), 0L)
22+
23+
/** Span instrumentation for [SentrySQLiteDriver]. */
1724
internal class SQLiteSpanInstrumentation(
1825
private val scopes: IScopes,
1926
private val dbMetadata: DbMetadata,
@@ -22,53 +29,32 @@ internal class SQLiteSpanInstrumentation(
2229
private val stackTraceFactory = SentryStackTraceFactory(scopes.options)
2330

2431
/**
25-
* Returns a start timestamp for a `db.sql.query` span.
32+
* Returns a timestamp in nanoseconds for use with [recordSpan]. Timestamp is ns-precise if the
33+
* active parent span uses a [SentryNanotimeDate] (the ordinary case); otherwise it's ms-precise.
2634
*
27-
* Exposed so callers can capture a wall-clock start before accumulating database time.
28-
* Internalizing the start time in [recordSpan] would shift spans to end-of-work on the trace
29-
* timeline, which is less desirable.
35+
* Note: Internalizing the start time in [recordSpan] would shift spans to end-of-work on the
36+
* trace timeline, which is less desirable; callers capture the start before doing database work
37+
* and pass it back to [recordSpan].
3038
*/
31-
fun startTimestamp(): SentryDate = scopes.options.dateProvider.now()
39+
fun startTimestamp(): Long =
40+
// Try to retain nanosecond precision + avoid SentryDate allocation...
41+
scopes.span?.childStartTimestampOrNull()
42+
// ...otherwise fall back to millisecond precision + allocate.
43+
?: scopes.options.dateProvider.now().nanoTimestamp()
3244

33-
/** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */
45+
/** Records a `db.sql.query` span. */
3446
fun recordSpan(
3547
sql: String,
36-
startTimestamp: SentryDate,
48+
startTimestampNanos: Long,
3749
durationNanos: Long,
3850
status: SpanStatus,
3951
throwable: Throwable? = null,
4052
) {
4153
val parent = scopes.span ?: return
42-
val nanoPrecisionStart = startTimestamp.repairPrecision(anchor = parent.startDate)
43-
val endTimestamp = SentryLongDate(nanoPrecisionStart.nanoTimestamp() + durationNanos)
44-
parent.recordChild(sql, nanoPrecisionStart, endTimestamp, status, throwable)
45-
}
46-
47-
/**
48-
* Records a `db.sql.query` span from [startTimestamp] to the moment of invocation.
49-
*
50-
* "Coarse" in that it doesn't try to restore nanosecond precision for the start timestamp. Spans
51-
* that start within the same wall clock millisecond will share the same start time and may be
52-
* arbitrarily re-ordered by the Sentry UI.
53-
*/
54-
fun recordCoarseSpan(
55-
sql: String,
56-
startTimestamp: SentryDate,
57-
status: SpanStatus,
58-
throwable: Throwable? = null,
59-
) {
60-
val parent = scopes.span ?: return
61-
parent.recordChild(sql, startTimestamp, endTimestamp = null, status, throwable)
62-
}
54+
val startTimestamp = SentryLongDate(startTimestampNanos)
55+
val endTimestamp = SentryLongDate(startTimestampNanos + durationNanos)
6356

64-
private fun ISpan.recordChild(
65-
sql: String,
66-
startTimestamp: SentryDate,
67-
endTimestamp: SentryDate?,
68-
status: SpanStatus,
69-
throwable: Throwable?,
70-
) {
71-
startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY).apply {
57+
parent.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY).apply {
7258
spanContext.origin = SQLITE_TRACE_ORIGIN
7359
throwable?.let { this.throwable = it }
7460

@@ -96,26 +82,15 @@ internal class SQLiteSpanInstrumentation(
9682
scopes: IScopes = ScopesAdapter.getInstance(),
9783
): SQLiteSpanInstrumentation =
9884
SQLiteSpanInstrumentation(scopes, dbMetadataFromFileName(fileName))
99-
100-
/**
101-
* Returns [SQLiteSpanInstrumentation] based on
102-
* [SupportSQLiteOpenHelper.databaseName][androidx.sqlite.db.SupportSQLiteOpenHelper.databaseName].
103-
*/
104-
fun fromDatabaseName(
105-
databaseName: String?,
106-
scopes: IScopes = ScopesAdapter.getInstance(),
107-
): SQLiteSpanInstrumentation =
108-
SQLiteSpanInstrumentation(scopes, dbMetadataFromDatabaseName(databaseName))
10985
}
11086
}
11187

11288
/**
113-
* Repairs the receiver's [nanoTimestamp][SentryDate.nanoTimestamp] if needed so that it actually
114-
* has nanosecond precision.
89+
* Computes a start timestamp with nanosecond precision for the child of the receiver span. Returns
90+
* null if nanosecond precision isn't possible.
11591
*
116-
* Designed for use with spans whose start timestamps are [SentryNanotimeDate]s. Without repair,
117-
* those timestamps will be aligned to the same millisecond at transport, and the Sentry UI will
118-
* arbitrarily reorder them:
92+
* Lets us improve the display of spans in the Sentry UI. If timestamps are only ms-precise, the
93+
* Sentry UI will left-align and arbitrarily reorder spans that share the same wall clock ms:
11994
* ```
12095
* (Relative start times out of order)
12196
* ↓
@@ -128,19 +103,22 @@ internal class SQLiteSpanInstrumentation(
128103
* even though their execution was staggered)
129104
* ```
130105
*
131-
* Repair ensures proper ordering and lets the spans stagger:
106+
* Nanosecond precision ensures proper ordering and lets the spans stagger:
132107
* ```
133108
* Parent span ├█████████████┤
134109
* BEGIN IMMEDIATE TRANSACTION ├████┤ 0.02 ms
135110
* INSERT INTO `my_db` … ├██┤ 0.30 ms
136111
* END TRANSACTION ├███┤ 0.33 ms
137112
* ```
138113
*/
139-
internal fun SentryDate.repairPrecision(anchor: SentryDate?): SentryDate =
140-
if (anchor is SentryNanotimeDate) {
141-
// Compute a new timestamp with nanosecond precision by using the anchor as the epoch instant
142-
// and adding to it the diff of this.nanos - anchor.nanos.
143-
SentryLongDate(anchor.laterDateNanosTimestampByDiff(this))
144-
} else {
145-
this
114+
internal fun ISpan.childStartTimestampOrNull(): Long? {
115+
if (startDate !is SentryNanotimeDate) {
116+
return null
146117
}
118+
119+
val parentWallClockNanos = startDate.nanoTimestamp()
120+
val parentMonotonicNanos = startDate.diff(EMPTY_NANO_TIME)
121+
val elapsedSinceParentStart = System.nanoTime() - parentMonotonicNanos
122+
// Return the child's absolute start time.
123+
return parentWallClockNanos + elapsedSinceParentStart
124+
}

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

Lines changed: 6 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
package io.sentry.sqlite
22

33
import androidx.sqlite.SQLiteStatement
4-
import io.sentry.SentryDate
54
import io.sentry.SpanStatus
65

76
/**
@@ -22,7 +21,7 @@ internal class SentrySQLiteStatement(
2221
private val nanoTimeProvider: () -> Long = { System.nanoTime() },
2322
) : SQLiteStatement by delegate {
2423

25-
private var firstStepTimestamp: SentryDate? = null
24+
private var firstStepTimestampNanos: Long? = null
2625
private var accumulatedDbNanos: Long = 0L
2726
private var stepsComplete = false
2827
private var closed = false
@@ -35,8 +34,8 @@ internal class SentrySQLiteStatement(
3534

3635
val beforeNanos = nanoTimeProvider()
3736
return try {
38-
if (firstStepTimestamp == null) {
39-
firstStepTimestamp = spans.startTimestamp()
37+
if (firstStepTimestampNanos == null) {
38+
firstStepTimestampNanos = spans.startTimestamp()
4039
}
4140

4241
stepsComplete = !delegate.step()
@@ -71,10 +70,10 @@ internal class SentrySQLiteStatement(
7170
}
7271

7372
private fun recordSpan(status: SpanStatus, throwable: Throwable? = null) {
74-
val start = firstStepTimestamp ?: return
73+
val startNanos = firstStepTimestampNanos ?: return
7574
val duration = accumulatedDbNanos
76-
firstStepTimestamp = null
75+
firstStepTimestampNanos = null
7776
accumulatedDbNanos = 0L
78-
spans.recordSpan(sql, start, duration, status, throwable)
77+
spans.recordSpan(sql, startNanos, duration, status, throwable)
7978
}
8079
}
Lines changed: 100 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,100 @@
1+
package io.sentry.sqlite
2+
3+
import io.sentry.DateUtils
4+
import io.sentry.ISpan
5+
import io.sentry.SentryLongDate
6+
import io.sentry.SentryNanotimeDate
7+
import java.util.Date
8+
import kotlin.test.Test
9+
import kotlin.test.assertEquals
10+
import kotlin.test.assertNull
11+
import kotlin.test.assertTrue
12+
import org.mockito.kotlin.mock
13+
import org.mockito.kotlin.whenever
14+
15+
class ChildStartTimestampOrNullTest {
16+
17+
@Test
18+
fun `returns parent wall clock plus elapsed monotonic time since parent started`() {
19+
val wallClockMillis = 1_000_000L
20+
val elapsedNanos = 500_000L
21+
val parentMonotonicNanos = System.nanoTime() - elapsedNanos
22+
val span = spanWithNanotimeStart(wallClockMillis, parentMonotonicNanos)
23+
24+
val timestamp = span.childStartTimestampOrNull()!!
25+
26+
val elapsedSinceParentStart = timestamp - DateUtils.millisToNanos(wallClockMillis)
27+
assertTrue(elapsedSinceParentStart >= elapsedNanos)
28+
assertTrue(elapsedSinceParentStart < elapsedNanos + TEST_SLACK_NANOS)
29+
}
30+
31+
@Test
32+
fun `same millisecond wall clocks with different monotonic offsets produce distinct ordered timestamps`() {
33+
val wallClockMillis = 1_000_000L
34+
val wallClockNanos = DateUtils.millisToNanos(wallClockMillis)
35+
val earlierParentMonotonicNanos = System.nanoTime() - 200_000L
36+
val laterParentMonotonicNanos = System.nanoTime() - 800_000L
37+
val earlierSpan = spanWithNanotimeStart(wallClockMillis, earlierParentMonotonicNanos)
38+
val laterSpan = spanWithNanotimeStart(wallClockMillis, laterParentMonotonicNanos)
39+
40+
assertEquals(
41+
earlierSpan.startDate.nanoTimestamp(),
42+
laterSpan.startDate.nanoTimestamp(),
43+
"Raw parent timestamps share the same ms-quantized value",
44+
)
45+
46+
val earlier = earlierSpan.childStartTimestampOrNull()!!
47+
val later = laterSpan.childStartTimestampOrNull()!!
48+
49+
assertTrue(earlier > wallClockNanos)
50+
assertTrue(later > wallClockNanos)
51+
assertTrue(earlier < later)
52+
assertTrue(later - earlier >= 500_000L)
53+
}
54+
55+
@Test
56+
fun `returns parent wall clock when no monotonic time has elapsed since parent started`() {
57+
val wallClockMillis = 1_000_000L
58+
val parentMonotonicNanos = System.nanoTime()
59+
val span = spanWithNanotimeStart(wallClockMillis, parentMonotonicNanos)
60+
61+
val elapsedSinceParentStart =
62+
span.childStartTimestampOrNull()!! - DateUtils.millisToNanos(wallClockMillis)
63+
assertTrue(elapsedSinceParentStart >= 0L)
64+
assertTrue(elapsedSinceParentStart < TEST_SLACK_NANOS)
65+
}
66+
67+
@Test
68+
fun `works when parent wall clock differs from millisecond baseline`() {
69+
val wallClockMillis = 1_000_001L
70+
val elapsedNanos = 1_500_000L
71+
val parentMonotonicNanos = System.nanoTime() - elapsedNanos
72+
val span = spanWithNanotimeStart(wallClockMillis, parentMonotonicNanos)
73+
74+
val elapsedSinceParentStart =
75+
span.childStartTimestampOrNull()!! - DateUtils.millisToNanos(wallClockMillis)
76+
assertTrue(elapsedSinceParentStart >= elapsedNanos)
77+
assertTrue(elapsedSinceParentStart < elapsedNanos + TEST_SLACK_NANOS)
78+
}
79+
80+
@Test
81+
fun `returns null when start date is not SentryNanotimeDate`() {
82+
val span = mock<ISpan>()
83+
whenever(span.startDate).thenReturn(SentryLongDate(DateUtils.millisToNanos(1_000_000L)))
84+
85+
assertNull(span.childStartTimestampOrNull())
86+
}
87+
88+
private fun spanWithNanotimeStart(wallClockMillis: Long, parentMonotonicNanos: Long): ISpan {
89+
val startDate = SentryNanotimeDate(Date(wallClockMillis), parentMonotonicNanos)
90+
val span = mock<ISpan>()
91+
whenever(span.startDate).thenReturn(startDate)
92+
return span
93+
}
94+
95+
companion object {
96+
97+
// Upper bound for monotonic drift while the test body runs.
98+
private const val TEST_SLACK_NANOS = 50_000_000L
99+
}
100+
}

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

Lines changed: 0 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -13,14 +13,6 @@ class DbMetadataTest {
1313
)
1414
}
1515

16-
@Test
17-
fun `dbMetadataFromDatabaseName returns in-memory system with no db name when databaseName is null`() {
18-
assertEquals(
19-
DbMetadata(name = null, system = DB_SYSTEM_IN_MEMORY),
20-
dbMetadataFromDatabaseName(null),
21-
)
22-
}
23-
2416
@Test
2517
fun `dbMetadataFromFileName returns sqlite system and db name for unix path`() {
2618
assertEquals(

0 commit comments

Comments
 (0)