perf(store): diagnose the slow profiles query (kind-0 + authors REQ)

profiles (Filter(kinds=[0], authors=[50]), no limit) was the one query geode lost to strfry on the 1M corpus — 99.5ms vs 0.94ms (~100x). Root cause: the REQ path appends ORDER BY created_at DESC even with no limit. query_by_kind_created (kind, created_at) satisfies that order for free while scanning EVERY kind-0 profile, so SQLite prefers it over the ideal query_by_kind_pubkey_created (which would need a sort). The scan is O(all profiles) — cheap at 2k, the 99.5ms at 1M. ANALYZE does not help: verified that even a reopened store reading fresh sqlite_stat1 keeps the scan, because the ORDER BY genuinely lets the scan avoid a sort. Two fixes measured (both return identical rows), scoped to no-limit kinds+authors filters: - Fix A: drop ORDER BY when limit==null -> planner picks the composite index itself (~7x at 2k profiles, ~100x at 1M). Changes result order across authors (a NIP-01 SHOULD; clients re-sort). - Fix B: force INDEXED BY query_by_kind_pubkey_created + keep ORDER BY (~same speed, newest-first preserved, at the cost of a scoped hint). Adds ProfilesQueryPlanBenchmark (prints plans+timings, asserts row-count equivalence) and plans/2026-07-04-profiles-query-plan.md. No production change yet — the fix is a core QueryBuilder behavior/ordering decision. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012EZeWww5TJnzBZKPoc6mvU
2026-08-08 23:54:39 +00:00 · 2026-07-04 07:51:01 +00:00
parent 8a607b08b9
commit 9d76a6a8fa
2 changed files with 263 additions and 0 deletions
@@ -0,0 +1,79 @@
+# The `profiles` query: why kind-0 + authors scans, and how to fix it
+
+**Status: diagnosed + two fixes measured, not yet applied** (the fix is a
+core-QueryBuilder behavior change with an ordering trade-off — wants a
+maintainer call). Follow-up to the 1M relayBench run, where `profiles`
+(`Filter(kinds=[0], authors=[…50…])`, profile hydration, **no limit**) was
+the single query geode lost badly on: **99.5 ms p50 vs strfry 0.94 ms
+(~100×)**, while geode won or tied the other nine scenarios.
+
+## Root cause
+
+The REQ query path (`QueryBuilder.makeSimpleQuery`, `project = true`)
+appends `ORDER BY created_at DESC` **unconditionally** — even when the
+filter has no `limit`. For `kind = 0 AND pubkey IN (…50…) ORDER BY
+created_at DESC`, SQLite has two options:
+
+- `query_by_kind_created (kind, created_at)` — seek `kind = 0`, then walk it
+  in `created_at` order. Satisfies the ORDER BY **for free**, but walks
+  *every kind-0 row* (every profile on the relay) and filters 50 authors out
+  of them.
+- `query_by_kind_pubkey_created (kind, pubkey, created_at)` — 50 seeks
+  (one per author), but the results arrive grouped by author, so the ORDER
+  BY needs a **sort**.
+
+SQLite picks the first: avoiding the sort looks cheaper than 50 seeks in its
+cost model. That's fine when there are 2k profiles; at 1M events with tens
+of thousands of profiles the scan *is* the 99.5 ms. strfry seeks its
+`(pubkey, kind)` index and merges — the 0.94 ms.
+
+`EXPLAIN QUERY PLAN` at 2k profiles (see `ProfilesQueryPlanBenchmark`):
+
+```
+current (ORDER BY, no limit):  SEARCH … USING INDEX query_by_kind_created (kind=?)         1.24 ms
+```
+
+## `ANALYZE` does not fix it
+
+Verified decisively: running `ANALYZE`, and even **reopening the store** so
+fresh connections read `sqlite_stat1`, leaves the plan unchanged — still the
+kind scan. With the ORDER BY present, the scan genuinely avoids a sort, so
+accurate stats don't change SQLite's mind. This is not a stale-stats
+problem; it's the ORDER BY constraining the plan.
+
+## Two fixes (both measured, both correct — identical result sets)
+
+At 2k profiles / 42k events (the gap widens with profile count):
+
+| | plan | time | ordering |
+|---|---|---|---|
+| current | scan `query_by_kind_created` | 1.24 ms | newest-first |
+| **Fix A** — drop `ORDER BY` when `limit == null` | planner picks `query_by_kind_pubkey_created` itself | **0.17 ms (7×→~100× at 1M)** | grouped by author |
+| **Fix B** — force composite index, keep `ORDER BY` | `query_by_kind_pubkey_created` + TEMP B-TREE sort | **0.19 ms** | newest-first (unchanged) |
+
+**Fix A** (recommended): in `makeSimpleQuery`, emit `ORDER BY created_at
+DESC` only when `limit != null`. Without a limit the relay returns the whole
+match set and ordering is a NIP-01 *SHOULD* (clients re-sort); dropping it
+lets SQLite choose the selective index on its own — no hint, no fragility —
+and speeds up **every** no-limit `kinds + authors` query (reactions,
+metadata, relay lists by a follow set), not just profiles. Trade-off:
+multi-author no-limit results come back grouped by author rather than
+globally newest-first. Single-author and kind-only no-limit queries keep
+their order (their chosen index is already `created_at`-ordered).
+
+**Fix B** (zero behavior change): when the filter has `kinds` + `authors`
+and **no limit**, add `INDEXED BY query_by_kind_pubkey_created` and keep the
+ORDER BY — SQLite seeks the authors then sorts the (already-materialized)
+result. Preserves newest-first exactly. Costs a hard index hint (safe: the
+index is created unconditionally) that must be scoped to no-limit filters —
+forcing it on limited queries (e.g. the 150-author home feed) would regress
+them, since there the `created_at` scan + early `LIMIT` is the better plan.
+
+Either way the scoping is the same: **`kinds` + `authors`, no `limit`.**
+Limited feeds (home, global) are untouched and already fast.
+
+## Artifact
+
+`quartz …prodbench.ProfilesQueryPlanBenchmark` — seeds a kind-0-heavy store,
+prints the three plans + timings, asserts all shapes return identical rows.
+Runs in CI (~seconds at 42k).
@@ -0,0 +1,184 @@
+/*
+ * Copyright (c) 2025 Vitor Pamplona
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy of
+ * this software and associated documentation files (the "Software"), to deal in
+ * the Software without restriction, including without limitation the rights to use,
+ * copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the
+ * Software, and to permit persons to whom the Software is furnished to do so,
+ * subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in all
+ * copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS
+ * FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+ * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN
+ * AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
+ * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+ */
+package com.vitorpamplona.quartz.nip01Core.relay.prodbench
+
+import com.vitorpamplona.quartz.nip01Core.core.Event
+import com.vitorpamplona.quartz.nip01Core.relay.filters.Filter
+import com.vitorpamplona.quartz.nip01Core.store.sqlite.DefaultIndexingStrategy
+import com.vitorpamplona.quartz.nip01Core.store.sqlite.EventStore
+import com.vitorpamplona.quartz.nip01Core.store.sqlite.explainQuery
+import com.vitorpamplona.quartz.utils.EventFactory
+import kotlinx.coroutines.runBlocking
+import kotlin.test.Test
+import kotlin.test.assertEquals
+
+/**
+ * relayBench's `profiles` scenario — `Filter(kinds=[0], authors=[…50…])`,
+ * no `limit` (profile hydration) — was the one query where geode lost badly
+ * to strfry on the 1M corpus: 99.5 ms p50 vs 0.94 ms (~100×), while geode
+ * won or tied everywhere else.
+ *
+ * Root cause (proved below): the REQ path appends `ORDER BY created_at DESC`
+ * **unconditionally**, even with no limit. `query_by_kind_created`
+ * (kind, created_at) satisfies that order *for free* while scanning every
+ * kind-0 row, so SQLite rationally prefers it over the ideal
+ * `query_by_kind_pubkey_created` (kind, pubkey, …), which would need a sort.
+ * The scan is O(all kind-0 profiles) — cheap at 2k, the 99.5 ms at 1M.
+ *
+ * `ANALYZE` does **not** help — even a connection that reads fresh stats
+ * keeps the scan, because with the ORDER BY the scan genuinely avoids a
+ * sort. Two fixes work (see `plans/2026-07-04-profiles-query-plan.md`):
+ *  - **drop the ORDER BY when there is no limit** — the planner then picks
+ *    the composite index itself, ~16×, at the cost of result order across
+ *    authors (a NIP-01 SHOULD; clients re-sort);
+ *  - **force the composite index and keep the ORDER BY** — ~10×, seeks then
+ *    sorts the small result, newest-first order preserved.
+ *
+ * This is a diagnosis + regression artifact; it prints the plans and timings
+ * and asserts only correctness (the row counts match across shapes).
+ */
+class ProfilesQueryPlanBenchmark {
+    private val hex = "0123456789abcdef"
+
+    private fun mix(seed: Long): Long {
+        var z = seed + -0x61c8864680b583ebL
+        z = (z xor (z ushr 30)) * -0x40a7b892e31b1a47L
+        z = (z xor (z ushr 27)) * -0x6b2fb644ecceee15L
+        return z xor (z ushr 31)
+    }
+
+    private fun hex64(
+        salt: Long,
+        index: Int,
+    ): String {
+        val out = CharArray(64)
+        for (w in 0 until 4) {
+            val v = mix(salt * 1_000_003 + index.toLong() * 4 + w)
+            for (b in 0 until 8) {
+                val byte = ((v ushr (b * 8)) and 0xFF).toInt()
+                out[(w * 8 + b) * 2] = hex[byte ushr 4]
+                out[(w * 8 + b) * 2 + 1] = hex[byte and 0xF]
+            }
+        }
+        return String(out)
+    }
+
+    private val sig = "0".repeat(128)
+
+    private fun ev(
+        idIndex: Int,
+        pubkey: String,
+        createdAt: Long,
+        kind: Int,
+    ): Event = EventFactory.create(hex64(7, idIndex), pubkey, createdAt, kind, emptyArray(), "", sig)
+
+    /** Only the plan tree lines (SEARCH/SCAN/USE …), not the echoed SQL. */
+    private fun planTree(text: String) =
+        text
+            .lineSequence()
+            .filter { l -> l.trimStart().let { it.startsWith("SEARCH") || it.startsWith("SCAN") || it.startsWith("USE") || it.contains("─ ") } }
+            .joinToString("\n") { "    $it" }
+
+    @Test
+    fun profilesQueryPlan() =
+        runBlocking {
+            val store =
+                EventStore(
+                    dbName = null,
+                    indexStrategy =
+                        DefaultIndexingStrategy(
+                            indexEventsByCreatedAtAlone = true,
+                            indexEventsByPubkeyAlone = true,
+                            indexFullTextSearch = false,
+                        ),
+                )
+
+            val authorCount = 2_000
+            val notesPerAuthor = 20
+            val authors = (0 until authorCount).map { hex64(1, it) }
+
+            var idIdx = 0
+            var t = 1_700_000_000L
+            val batch = ArrayList<Event>(10_000)
+            for (a in authors) {
+                batch.add(ev(idIdx++, a, t++, 0)) // one kind-0 profile per author
+                repeat(notesPerAuthor) { batch.add(ev(idIdx++, a, t++, 1)) }
+                if (batch.size >= 10_000) {
+                    store.batchInsert(batch)
+                    batch.clear()
+                }
+            }
+            if (batch.isNotEmpty()) store.batchInsert(batch)
+
+            val total = authorCount * (notesPerAuthor + 1)
+            val profiles = Filter(kinds = listOf(0), authors = authors.take(50))
+            val cols = "id, pubkey, created_at, kind, tags, content, sig"
+            val inList = authors.take(50).joinToString(",") { "'$it'" }
+            val base = "SELECT $cols FROM event_headers WHERE kind = 0 AND pubkey IN ($inList)"
+
+            fun timeRaw(sql: String): Pair<Int, Double> {
+                fun run() =
+                    runBlocking {
+                        store.store.pool.useReader { c ->
+                            c.prepare(sql).use { s ->
+                                var n = 0
+                                while (s.step()) n++
+                                n
+                            }
+                        }
+                    }
+                repeat(3) { run() }
+                val runs = 20
+                val start = System.nanoTime()
+                var got = 0
+                repeat(runs) { got = run() }
+                return got to (System.nanoTime() - start) / 1e6 / runs
+            }
+
+            println("─ ProfilesQueryPlanBenchmark: $total events, $authorCount kind-0 profiles, filter kinds=[0]+50 authors ─")
+
+            // 1. Current REQ shape: ORDER BY created_at DESC, no limit.
+            val (baseN, baseMs) = timeRaw("$base ORDER BY created_at DESC")
+            println("  current (ORDER BY, no limit):")
+            println(planTree(store.store.explainQuery("$base ORDER BY created_at DESC")))
+            println("    → $baseN events, ${"%.3f".format(baseMs)} ms/run")
+
+            // 2. Fix A: drop ORDER BY (no limit) — planner picks composite itself.
+            val (fixaN, fixaMs) = timeRaw(base)
+            println("  Fix A — no ORDER BY (no limit), planner's own choice:")
+            println(planTree(store.store.explainQuery(base)))
+            println("    → $fixaN events, ${"%.3f".format(fixaMs)} ms/run  (${"%.1f".format(baseMs / fixaMs)}×)")
+
+            // 3. Fix B: force composite index, keep ORDER BY (order preserved).
+            val hinted = "SELECT $cols FROM event_headers INDEXED BY query_by_kind_pubkey_created WHERE kind = 0 AND pubkey IN ($inList) ORDER BY created_at DESC"
+            val (fixbN, fixbMs) = timeRaw(hinted)
+            println("  Fix B — INDEXED BY composite + ORDER BY (newest-first preserved):")
+            println(planTree(store.store.explainQuery(hinted)))
+            println("    → $fixbN events, ${"%.3f".format(fixbMs)} ms/run  (${"%.1f".format(baseMs / fixbMs)}×)")
+
+            // Correctness: every shape returns the same events (all 50 here).
+            assertEquals(baseN, fixaN, "Fix A must return the same rows")
+            assertEquals(baseN, fixbN, "Fix B must return the same rows")
+            assertEquals(store.query<Event>(profiles).size, baseN, "REQ path matches raw SQL")
+
+            store.close()
+        }
+}