Skip to content

rebuild_analytics runs at 21 msg/s on a 652k-message archive (~8.6 h) #424

Description

@bitjson

(Fable 5:)

Title: main (0.7.0): rebuild_analytics runs at 21 msg/s on a 652k-message archive (~8.6 h) — the keyset chunk JOINs conversations, which frankensqlite materializes in full per chunk; the 0.7.0 upgrade forces this rebuild inside cass index preflight with no progress events (follow-up to #412)

Summary

After upgrading from v0.6.26 to a main build (a06d389, version 0.7.0), the first cass index on a 1.9 GB archive (652,668 messages / 809 conversations) sat in phase: "preparing", items 0/0 for hours with a single thread at 100 % CPU, no I/O and no progress events. CASS_TRACE_FILE shows what it was doing:

INFO cass::indexer::preflight  ... reclassify_legacy_omp ...
INFO cass::analytics  analytics_rebuild_start   total_messages=652668
INFO cass::analytics  analytics_rebuild_progress processed=10000 last_id=10000 chunk=10000 inserted=10000 elapsed_secs=485.9 msgs_per_sec=21
INFO cass::analytics  analytics_rebuild_progress processed=20000 ... elapsed_secs=939.9 msgs_per_sec=21
INFO cass::analytics  analytics_rebuild_progress processed=30000 ... elapsed_secs=1382.5 msgs_per_sec=22
INFO cass::analytics  analytics_rebuild_progress processed=40000 ... elapsed_secs=1833.7 msgs_per_sec=22

Every 10,000-row chunk takes ~450 s, independent of cursor position → ~8.6 h for one rebuild_analytics(), followed by rebuild_token_daily_stats() and rebuild_daily_stats(). Each chunk is also accompanied by one WARN fsqlite_btree::cursor read-witness cap reached on cursor ... root_page=<messages> cap=16384, i.e. the engine reads ≥ 16k pages of messages per chunk.

#412 made the pagination itself linear (keyset instead of OFFSET); this is the next wall behind it. Two problems compound:

  1. The chunk query shape is pathological on the pinned engine. rebuild_analytics_since (src/storage/sqlite.rs:17119, chunk query at :17140; same shape at :17221) pages with

    SELECT m.id, m.idx, m.role, m.content, m.extra_json, m.extra_bin, m.created_at,
           c.id, c.started_at, c.source_id, c.workspace_id,
           COALESCE((SELECT a.slug FROM agents a WHERE a.id = c.agent_id), 'unknown')
    FROM messages m JOIN conversations c ON m.conversation_id = c.id
    WHERE m.id > ?1 AND COALESCE(m.created_at, c.started_at, 0) >= ?2
    ORDER BY m.id LIMIT ?3

    On fsqlite 0.3.8 a JOIN under ORDER BY … LIMIT is materialized in full before the limit is applied: in an isolated repro against the same archive, the JOIN keyset with LIMIT 100 costs the same as with LIMIT 10000 (8–18 s), the exact query above costs 635 s per 10k rows, while the identical predicate on messages alone returns 10k rows in 0.12–0.18 s (and 100 rows in 3 ms at id > 640000). Stock SQLite runs the exact query in 0.06 s. It reproduces on a synthetic archive too — filed on the engine side as frankensqlite#386; the cass-side observation is that the rebuild depends on a plan the engine does not produce.

  2. The 0.7.0 upgrade path forces this rebuild inside cass index preflight, unconditionally and unabortably-in-practice. The watch_startup:reclassify_legacy_omp preflight phase (src/indexer/mod.rs:13870-13872reclassify_legacy_omp_conversations()) runs on the first index after upgrade (31 pi_agent conversations here) and then rebuilds analytics (rebuild_analytics(), rebuild_token_daily_stats(), rebuild_daily_stats()) before scanning can start. It emits no indexer progress events, so with the default stall budget (abort_threshold_secs: 300) the watchdog exits 70 partway through; rebuild_analytics has no checkpoint (v0.6.23: daily_stats rebuild has no checkpointing — every interrupted run restarts the message scan from zero (4+ identical restarts measured in one day) #386token_daily_stats now has a resumable cursor on main, message_metrics/daily_stats still restart from zero), so the next run starts from zero — the upgrade can never complete on a large archive unless the operator discovers CASS_INDEX_STALL_ABORT_SECS=0, and even then it is an 8-hour preflight. The routine-indexing defer_analytics_updates_guard (mod.rs:13484, CASS_DEFER_ANALYTICS_UPDATES) does not cover this path.

Validated rewrite (measured locally, same archive)

Keep the keyset on messages alone and resolve the two dimension tables from memory — both are tiny relative to messages (conversations ≈ number of sessions, agents ≈ number of connectors):

  • once per rebuild: SELECT id, slug FROM agentsHashMap<i64, String>; SELECT id, started_at, source_id, workspace_id, agent_id FROM conversationsHashMap<i64, (Option<i64>, String, Option<i64>, String /*slug or 'unknown'*/)>;
  • per chunk: SELECT m.id, m.idx, m.role, m.content, m.extra_json, m.extra_bin, m.created_at, m.conversation_id FROM messages m WHERE m.id > ?1 ORDER BY m.id LIMIT ?2;
  • apply COALESCE(m.created_at, c.started_at, 0) >= cutoff in Rust after the lookup; drop rows whose conversation is missing (what the JOIN did); advance the cursor by the last fetched id (not the last kept one) so filtered rows cannot stall it, and terminate on fetched < CHUNK_SIZE.

Measured after the rewrite: per-chunk SELECT ~0.2 s; the first chunks run at 328–338 msg/s (was 21). The remaining ~3 ms/row is the insert side (one INSERT OR IGNORE INTO message_metrics statement per row + the rollup upserts), not the scan.

Second finding (same run): with the whole rebuild inside one transaction, the per-chunk cost then grows linearly — 30 s → 45 → 67 → 79 → 73 → 77 → 104 → 107 s by chunk 11 (+~8 s per chunk, load ~4 on 24 cores, memory flat at 6 GB), which extrapolates to ~4.5 h for 652k rows. Committing after every chunk (tx.commit()?; tx = self.conn.transaction()?; at the end of the loop body) holds every chunk at the base cost: chunk 10 = 33 s, 354 msg/s sustained → the full rebuild completes in ~30 min. Per-chunk commits also leave a resumable prefix behind (the state marker already exists; only last_id would need persisting — the same cursor pattern rebuild_token_daily_stats now uses). Output rows are identical in shape; the only behavioural difference is that --since rebuilds now scan every messages row (0.2 s per 10k) instead of relying on the SQL cutoff — the rollup rows produced are the same.

Third finding (same run): rebuild_daily_stats() has the same problem when message_metrics is complete. Its per-conversation page (src/storage/sqlite.rs:17477-17485) SELECT m.idx, mm.content_chars FROM messages m INDEXED BY sqlite_autoindex_messages_1 JOIN message_metrics mm ON mm.message_id = m.id WHERE m.conversation_id = ?1 AND m.idx > ?2 ORDER BY m.idx LIMIT ?3 costs ~8 s per call on this engine regardless of the conversation's size (measured 8.26 / 8.06 / 7.99 s for 8-, 15- and 854-message conversations — the join is materialized before the index lookup applies), so the step runs for hours across 809 conversations with no progress events. The JOIN-free branch the function already has (LENGTH(CAST(m.content AS BLOB)) from messages alone, same byte semantics) costs ~0.1 s per page with the INDEXED BY hint and ~3 ms without it. Locally validated by forcing that branch (an env opt-out): daily_stats over 652,668 messages = 15 s instead of ~14 s per conversation. A lookup map from a single-table message_metrics keyset would keep the metrics-based path if the tokens matter.

Suggested fixes

  1. Commit per chunk (see above) — on this engine one long write transaction makes each successive chunk slower.
  2. Rewrite the rebuild_analytics_since chunk as above, and give rebuild_daily_stats the same treatment (its metrics-JOIN page is the Q7 shape in frankensqlite#386); rebuild_token_daily_stats keysets over conversations with only a correlated subquery and is fine (19 s here).
  3. Make the upgrade-time analytics rebuild honour CASS_DEFER_ANALYTICS_UPDATES (or run it after the lexical publish, as a resumable job) and emit progress events the stall watchdog recognises, so a first index after upgrade cannot be killed by the default 300 s abort with nothing to resume from.
  4. analytics_rebuild_progress already carries last_id — persisting it (as token_daily_stats_rebuild_cursor now does for Track B) would make an interrupted preflight rebuild resumable and close the message_metrics half of v0.6.23: daily_stats rebuild has no checkpointing — every interrupted run restarts the message scan from zero (4+ identical restarts measured in one day) #386.

Environment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions