Skip to content

Commit 48f43f7

Browse files
0xadam-brown0xadam-brown
authored
Merge 776deac into e52b4e4 
2 parents e52b4e4 + 776deac commit 48f43f7

8 files changed

Lines changed: 279 additions & 118 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.recordSpan(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.recordSpan(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: 63 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -1,17 +1,26 @@
11
package io.sentry.sqlite
22

33
import io.sentry.IScopes
4+
import io.sentry.ISpan
45
import io.sentry.Instrumenter
56
import io.sentry.ScopesAdapter
67
import io.sentry.SentryDate
78
import io.sentry.SentryLongDate
9+
import io.sentry.SentryNanotimeDate
810
import io.sentry.SentryStackTraceFactory
911
import io.sentry.SpanDataConvention
1012
import io.sentry.SpanStatus
13+
import java.util.Date
1114

1215
private const val SQLITE_TRACE_ORIGIN = "auto.db.sqlite"
1316

14-
/** 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]. */
1524
internal class SQLiteSpanInstrumentation(
1625
private val scopes: IScopes,
1726
private val dbMetadata: DbMetadata,
@@ -20,44 +29,32 @@ internal class SQLiteSpanInstrumentation(
2029
private val stackTraceFactory = SentryStackTraceFactory(scopes.options)
2130

2231
/**
23-
* 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.
2434
*
25-
* Exposed so callers can capture a wall-clock start before accumulating database time.
26-
* Internalizing the start time in [recordSpan] would shift spans to end-of-work on the trace
27-
* 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].
2838
*/
29-
fun startTimestamp(): SentryDate = scopes.options.dateProvider.now()
30-
31-
/** Records a `db.sql.query` span from [startTimestamp] to the moment of invocation. */
32-
fun recordSpan(
33-
sql: String,
34-
startTimestamp: SentryDate,
35-
status: SpanStatus,
36-
throwable: Throwable? = null,
37-
) {
38-
recordSpan(sql, startTimestamp, endTimestamp = null, status, throwable)
39-
}
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()
4044

41-
/** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */
45+
/** Records a `db.sql.query` span. */
4246
fun recordSpan(
4347
sql: String,
44-
startTimestamp: SentryDate,
48+
startTimestampNanos: Long,
4549
durationNanos: Long,
4650
status: SpanStatus,
4751
throwable: Throwable? = null,
4852
) {
49-
val endTimestamp = SentryLongDate(startTimestamp.nanoTimestamp() + durationNanos)
50-
recordSpan(sql, startTimestamp, endTimestamp, status, throwable)
51-
}
53+
val parent = scopes.span ?: return
54+
val startTimestamp = SentryLongDate(startTimestampNanos)
55+
val endTimestamp = SentryLongDate(startTimestampNanos + durationNanos)
5256

53-
private fun recordSpan(
54-
sql: String,
55-
startTimestamp: SentryDate,
56-
endTimestamp: SentryDate?,
57-
status: SpanStatus,
58-
throwable: Throwable?,
59-
) {
60-
scopes.span?.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY)?.apply {
57+
parent.startChild("db.sql.query", sql, startTimestamp, Instrumenter.SENTRY).apply {
6158
spanContext.origin = SQLITE_TRACE_ORIGIN
6259
throwable?.let { this.throwable = it }
6360

@@ -85,15 +82,43 @@ internal class SQLiteSpanInstrumentation(
8582
scopes: IScopes = ScopesAdapter.getInstance(),
8683
): SQLiteSpanInstrumentation =
8784
SQLiteSpanInstrumentation(scopes, dbMetadataFromFileName(fileName))
85+
}
86+
}
8887

89-
/**
90-
* Returns [SQLiteSpanInstrumentation] based on
91-
* [SupportSQLiteOpenHelper.databaseName][androidx.sqlite.db.SupportSQLiteOpenHelper.databaseName].
92-
*/
93-
fun fromDatabaseName(
94-
databaseName: String?,
95-
scopes: IScopes = ScopesAdapter.getInstance(),
96-
): SQLiteSpanInstrumentation =
97-
SQLiteSpanInstrumentation(scopes, dbMetadataFromDatabaseName(databaseName))
88+
/**
89+
* Computes a start timestamp with nanosecond precision for the child of the receiver span. Returns
90+
* null if nanosecond precision isn't possible.
91+
*
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:
94+
* ```
95+
* (Relative start times out of order)
96+
* ↓
97+
* Parent span ├█████████████┤
98+
* END TRANSACTION ├███┤ 0.33 ms
99+
* BEGIN IMMEDIATE TRANSACTION ├████┤ 0.02 ms
100+
* INSERT INTO `my_db` … ├██┤ 0.30 ms
101+
* ↑
102+
* (All spans share the same ms baseline
103+
* even though their execution was staggered)
104+
* ```
105+
*
106+
* Nanosecond precision ensures proper ordering and lets the spans stagger:
107+
* ```
108+
* Parent span ├█████████████┤
109+
* BEGIN IMMEDIATE TRANSACTION ├████┤ 0.02 ms
110+
* INSERT INTO `my_db` … ├██┤ 0.30 ms
111+
* END TRANSACTION ├███┤ 0.33 ms
112+
* ```
113+
*/
114+
internal fun ISpan.childStartTimestampOrNull(): Long? {
115+
if (startDate !is SentryNanotimeDate) {
116+
return null
98117
}
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
99124
}

‎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
}

‎sentry-android-sqlite/src/test/java/io/sentry/sqlite/ChildStartTimestampOrNullTest.kt‎

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)