diff --git a/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt b/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt index 558be462..93babc79 100644 --- a/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt +++ b/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt @@ -47,14 +47,13 @@ private class LoggingStatement( private val sql: String, private val onExecution: (SqlExecution) -> Unit, ) : SQLiteStatement by delegate { - private var startNanos = System.nanoTime() + private var startNanos = 0L private var rows = 0L private var failure: Throwable? = null - private var started = false - private var reported = false + private var active = false override fun step(): Boolean { - started = true + begin() val result = try { delegate.step() @@ -71,7 +70,6 @@ private class LoggingStatement( override fun reset() { report() delegate.reset() - begin() } override fun close() { @@ -80,17 +78,20 @@ private class LoggingStatement( } private fun report() { - if (!started || reported) return - reported = true + if (!active) return + active = false onExecution(SqlExecution(sql, System.nanoTime() - startNanos, rows, failure)) } + // Started on the first step, not on reset: Room's statement cache resets a statement when it is + // returned to the cache (BasePreparedStatementCache.CachedStatement.close), so timing from reset + // would count however long the statement idled there before its next use. private fun begin() { + if (active) return startNanos = System.nanoTime() rows = 0 failure = null - started = false - reported = false + active = true } } diff --git a/app/src/main/kotlin/com/subtracks/log/Log.kt b/app/src/main/kotlin/com/subtracks/log/Log.kt index a63ab126..bf9204c6 100644 --- a/app/src/main/kotlin/com/subtracks/log/Log.kt +++ b/app/src/main/kotlin/com/subtracks/log/Log.kt @@ -34,6 +34,11 @@ object Log { i("app", "started ${BuildConfig.VERSION_NAME} (${BuildConfig.VERSION_CODE}) on Android ${Build.VERSION.SDK_INT} ${Build.MODEL}") } + fun v( + tag: String, + message: String, + ) = log(LogLevel.VERBOSE, tag, message, null) + fun d( tag: String, message: String, @@ -83,7 +88,7 @@ object Log { fun interceptor(): Interceptor = Interceptor { chain -> val request = chain.request() - d("http", "${request.method} ${request.url}") + v("http", "${request.method} ${request.url}") try { val response = chain.proceed(request) if (response.code >= 400) { @@ -99,7 +104,11 @@ object Log { fun sql(execution: SqlExecution) { val failure = execution.error if (failure != null) { - e("sql", "failed: ${shortSql(execution.sql)}", failure) + if (isUpsertConflict(failure)) { + d("sql", "upsert fallback conflict: ${shortSql(execution.sql)}") + } else { + e("sql", "failed: ${shortSql(execution.sql)}", failure) + } return } if (!isSlowQuery(execution, SLOW_QUERY_MS)) return @@ -166,3 +175,17 @@ internal fun isSlowQuery( execution: SqlExecution, thresholdMs: Double, ): Boolean = execution.error == null && execution.durationMillis >= thresholdMs && isDataStatement(execution.sql) + +// Room's EntityUpsertAdapter implements @Upsert as an INSERT and, on a uniqueness conflict, catches +// the error and runs an UPDATE instead (EntityUpsertAdapter.checkUniquenessException). That failure +// is expected control flow, not an error worth alarming about. +private const val CONSTRAINT_UNIQUE_MESSAGE = "unique constraint failed" +private const val SQLITE_CONSTRAINT_PRIMARYKEY = "1555" +private const val SQLITE_CONSTRAINT_UNIQUE = "2067" + +internal fun isUpsertConflict(error: Throwable): Boolean { + val message = error.message?.lowercase() ?: return false + return message.contains(CONSTRAINT_UNIQUE_MESSAGE) || + message.contains(SQLITE_CONSTRAINT_PRIMARYKEY) || + message.contains(SQLITE_CONSTRAINT_UNIQUE) +} diff --git a/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt b/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt index c6ea39f3..1da27991 100644 --- a/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt +++ b/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt @@ -62,6 +62,25 @@ class DbLoggingTest { assertTrue(select.durationNanos > 0) } + @Test + fun doesNotCountIdleTimeBetweenReuses() { + driver().open(":memory:").use { connection -> + connection.prepare("CREATE TABLE t (id INTEGER PRIMARY KEY, name TEXT)").use { it.step() } + connection.prepare("INSERT INTO t (name) VALUES (?)").use { statement -> + statement.bindText(1, "a") + statement.step() + statement.reset() + Thread.sleep(250) + statement.bindText(1, "b") + statement.step() + statement.reset() + } + } + val inserts = executions.filter { it.sql.startsWith("INSERT") } + assertEquals(2, inserts.size) + inserts.forEach { assertTrue("${it.durationMillis}ms", it.durationNanos < 100_000_000) } + } + @Test fun recordsPrepareError() { driver().open(":memory:").use { connection -> diff --git a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt index 238466f8..a07722b1 100644 --- a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt +++ b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt @@ -150,6 +150,14 @@ class LogFileStoreTest { assertFalse(isReadStatement("INSERT INTO t VALUES (1)")) } + @Test + fun detectsUpsertConflictErrors() { + assertTrue(isUpsertConflict(IllegalStateException("UNIQUE constraint failed: playback_cursor.id"))) + assertTrue(isUpsertConflict(IllegalStateException("Error code: 1555, message: UNIQUE constraint failed"))) + assertTrue(isUpsertConflict(IllegalStateException("SQLITE_CONSTRAINT_UNIQUE 2067"))) + assertFalse(isUpsertConflict(IllegalStateException("no such table: songs"))) + } + private fun execution( milliseconds: Double, sql: String,