Skip to content

Commit 71d91b3

Browse files
committed
chore(android-sqlite): Repair start times of spans generated by SentrySQLiteDriver
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)).
1 parent 007c537 commit 71d91b3

3 files changed

Lines changed: 491 additions & 14 deletions

File tree

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -41,10 +41,10 @@ internal class SQLiteSpanManager(
4141
if (result is CrossProcessCursor) {
4242
return SentryCrossProcessCursor(result, this, sql) as T
4343
}
44-
spans.recordSpan(sql, startTimestamp, SpanStatus.OK)
44+
spans.recordCoarseSpan(sql, startTimestamp, SpanStatus.OK)
4545
result
4646
} catch (e: Throwable) {
47-
spans.recordSpan(sql, startTimestamp, SpanStatus.INTERNAL_ERROR, e)
47+
spans.recordCoarseSpan(sql, startTimestamp, SpanStatus.INTERNAL_ERROR, e)
4848
throw e
4949
}
5050
}

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

Lines changed: 47 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import io.sentry.Instrumenter
55
import io.sentry.ScopesAdapter
66
import io.sentry.SentryDate
77
import io.sentry.SentryLongDate
8+
import io.sentry.SentryNanotimeDate
89
import io.sentry.SentryStackTraceFactory
910
import io.sentry.SpanDataConvention
1011
import io.sentry.SpanStatus
@@ -28,26 +29,33 @@ internal class SQLiteSpanInstrumentation(
2829
*/
2930
fun startTimestamp(): SentryDate = scopes.options.dateProvider.now()
3031

31-
/** Records a `db.sql.query` span from [startTimestamp] to the moment of invocation. */
32+
/** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */
3233
fun recordSpan(
3334
sql: String,
3435
startTimestamp: SentryDate,
36+
durationNanos: Long,
3537
status: SpanStatus,
3638
throwable: Throwable? = null,
3739
) {
38-
recordSpan(sql, startTimestamp, endTimestamp = null, status, throwable)
40+
val parentStart = scopes.span?.startDate
41+
val nanoPrecisionStart = startTimestamp.repairPrecision(baseline = parentStart)
42+
val endTimestamp = SentryLongDate(nanoPrecisionStart.nanoTimestamp() + durationNanos)
43+
recordSpan(sql, nanoPrecisionStart, endTimestamp, status, throwable)
3944
}
4045

41-
/** Records a `db.sql.query` span from [startTimestamp] to [startTimestamp] + [durationNanos]. */
42-
fun recordSpan(
46+
/**
47+
* Records a `db.sql.query` span from [startTimestamp] to the moment of invocation.
48+
*
49+
* "Coarse" in that it doesn't provide a nanosecond precision for [SentryNanotimeDate]
50+
* [startTimestamp]s.
51+
*/
52+
fun recordCoarseSpan(
4353
sql: String,
4454
startTimestamp: SentryDate,
45-
durationNanos: Long,
4655
status: SpanStatus,
4756
throwable: Throwable? = null,
4857
) {
49-
val endTimestamp = SentryLongDate(startTimestamp.nanoTimestamp() + durationNanos)
50-
recordSpan(sql, startTimestamp, endTimestamp, status, throwable)
58+
recordSpan(sql, startTimestamp, endTimestamp = null, status, throwable)
5159
}
5260

5361
private fun recordSpan(
@@ -74,6 +82,38 @@ internal class SQLiteSpanInstrumentation(
7482
}
7583
}
7684

85+
/**
86+
* Repairs the receiver's [nanoTimestamp][SentryDate.nanoTimestamp] if needed so that it actually
87+
* has nanosecond precision.
88+
*
89+
* Designed for use with spans whose start timestamps are [SentryNanotimeDate]s. Without repair,
90+
* those timestamps will be aligned to the same millisecond at transport, and the Sentry UI will
91+
* arbitrarily reorder them:
92+
* ```
93+
* Parent span ├█████████████┤
94+
* END TRANSACTION ├███┤ 0.18 ms ← (Wrong order)
95+
* BEGIN IMMEDIATE TRANSACTION ├████┤ 0.25 ms
96+
* INSERT INTO `my_db` … ├██┤ 0.10 ms
97+
* ↑
98+
* (All spans share the same ms baseline
99+
* even though their execution was staggered)
100+
* ```
101+
*
102+
* Repair ensures proper ordering and lets the spans stagger:
103+
* ```
104+
* Parent span ├█████████████┤
105+
* BEGIN IMMEDIATE TRANSACTION ├████┤ 0.25 ms
106+
* INSERT INTO `my_db` … ├██┤ 0.10 ms
107+
* END TRANSACTION ├███┤ 0.18 ms
108+
* ```
109+
*/
110+
private fun SentryDate.repairPrecision(baseline: SentryDate?): SentryDate =
111+
if (baseline is SentryNanotimeDate) {
112+
SentryLongDate(baseline.laterDateNanosTimestampByDiff(this))
113+
} else {
114+
this
115+
}
116+
77117
companion object {
78118

79119
fun fromDatabaseName(databaseName: String?, scopes: IScopes = ScopesAdapter.getInstance()) =

0 commit comments

Comments
 (0)