Skip to content

Speed up llm logs filters, prompt -c and logging on large^H^H^Hnormal after few months :) databases - #1657

Open
rdslw wants to merge 1 commit into
simonw:mainfrom
rdslw:perf-log-lookup-indexes
Open

rdslw wants to merge 1 commit into
simonw:mainfrom
rdslw:perf-log-lookup-indexes

Conversation

@rdslw

@rdslw rdslw commented Sep 2, 2026 •

Copy link
Copy Markdown
Contributor

I updated PR after llm-0.37 release. please look at the comment below for accurate perfoemnce table measurements.

TL;DR: this PR offers substantial performance improvemnts via simple change:

End to end at 50x (hyperfine, including 1.2 s of startup): --tools 17.9 s → 1.24 s, -T 41.5 s → 1.26 s,


EXPLAIN QUERY PLAN over the queries llm logs runs shows five lookups that scan a whole table. Fine at hundreds of rows, painful as the store grows. This adds one migration with five indexes and a one-word query change:

  • parts(type, tool_name, message_hash) - the --tools / -T filters resolve "messages with a tool_result part" by scanning parts, the fastest-growing table, and building a transient automatic index on every query.
  • tool_calls, tool_results, tool_responses on response_id - the legacy extras and the legacy --tools filter probe these per listed response through correlated subqueries.
  • responses(conversation_id) - legacy --cid filtering; turns.thread_id got its index in m023, this column never did.
  • load_conversation() for prompt -c used a distinct union of threads and conversations, which materializes every id before taking one row. union all lets SQLite stop at the first row of each primary key; the outer limit 1 already discards any dual-write duplicate.

Measured on a copy of my logs.db (442 legacy responses, 359 turns, 1202 parts) and the same database replicated 50x (22k responses, 18k turns, 60k parts). Query timings, median of 15 runs:

Query real, before real, after 50x, before 50x, after
legacy extras for 20 rows (tool_calls + tool_results subqueries) 0.32 ms 0.09 ms 38.6 ms 0.10 ms
legacy --tools filter 0.13 ms 0.08 ms 4.3 ms 0.18 ms
legacy --cid filter 1.90 ms 0.03 ms 108.8 ms 0.03 ms
--tools filter (parts) 6.4 ms 0.4 ms 12 695 ms 27 ms
-T name filter (parts) 3.8 ms 0.2 ms 5 427 ms 11 ms
latest conversation for prompt -c (12k threads) - - 36 ms 0.1 ms

End to end at 50x, hyperfine mean of 3 runs (about 2 s of each is interpreter and plugin startup):

Command before after
llm logs list --tools -n 5 14.4 s 2.2 s
llm logs list -T Brave_context -n 5 42.1 s 2.2 s
llm logs list --cid ID -n 5 2.2 s 2.1 s

The five indexes add about 0.6% to the file size. If you prefer a smaller footprint on parts, a partial index on parts (tool_name, message_hash) where type = 'tool_result' serves the same query; happy to switch.

Created with help of Fable-5.1 during migration of llm-openai-codex from llm-0.32 to llm-0.33.

@rdslw
rdslw force-pushed the perf-log-lookup-indexes branch from ac77f6a to 07a9250 Compare November 3, 2026 22:24
…ry conversation id for 'prompt -c'

EXPLAIN QUERY PLAN over the queries llm logs issues showed five scans
that grow linearly with the store, and one more on every logged turn.

m028_log_lookup_indexes:
- parts(tool_name, message_hash) where type = 'tool_result': the
  --tools/-T filters resolve "messages carrying a tool_result part (of
  this name)". That was a full scan of parts - the fastest-growing
  table - plus a transient automatic index SQLite built on every
  query. The trailing message_hash makes the index covering for
  exactly that subquery. The index is partial on purpose: without
  sqlite_stat1, a full index that leads with type gets picked for
  every "type = ?" lookup, so _part_ids() and the message_tree view
  would read all parts of a type instead of one message's parts.
  Only queries that spell out type = 'tool_result' can use it.
- tool_calls/tool_results/tool_responses(response_id): the legacy
  extras and legacy --tools filter read these only through correlated
  subqueries on response_id - one full scan per listed response, and
  tool_results rows carry the tool outputs. tool_responses' primary
  key starts with tool_id, so it could not serve the probe either.
- responses(conversation_id): --cid on the legacy side was a full
  responses scan; turns got idx_turns_thread_id in m023 but the
  legacy column never got the equivalent.

load_conversation(): the latest-conversation lookup for 'prompt -c'
used a distinct union of threads and conversations, which materializes
every id from both tables before sorting for one row. 'union all' lets
SQLite stop at the first row of each primary key; the outer limit 1
already discards any dual-write duplicate.

TURN_SEARCH_INSERT_SQL: the turn_search refresh that LogStore.log runs
for every logged turn joined output_messages to messages and parts
with plain joins. SQLite cannot tell the recursive chain is short, so
it put parts in the outer loop and scanned the whole table per turn.
Cross joins keep output_messages outermost; the derived rows are the
same.

tests/test_migrate.py asserts migrate() leaves all five indexes in
place, the parts one partial.
@rdslw
rdslw force-pushed the perf-log-lookup-indexes branch from 07a9250 to a08d649 Compare November 3, 2026 23:53
@rdslw rdslw changed the title Index the columns 'llm logs' looks rows up by, use 'union all' for the latest-conversation lookup Speed up llm logs filters, prompt -c and logging on large databases Nov 5, 2026
@rdslw

rdslw commented Nov 5, 2026

Copy link
Copy Markdown
Contributor Author

@simonw I re-ran the numbers for this PR on top of 0.37.1 (rebased, now on b9786a2). They showed two regressions in the parts index I first proposed, and a write-path cost that is already in 0.37.1. I amended the commit on this branch to fix all three.

Setup. A copy of my logs.db (442 legacy responses, 407 turns, 709 messages, 1,422 parts) and the same rows replicated 10x and 50x (50x: 22,100 responses, 20,350 turns, 35,450 messages, 71,100 parts; keys rewritten consistently, foreign_key_check clean). Python 3.15.0, SQLite 3.51.2, LLM_LOAD_PLUGINS="", warm cache. In-process medians of 15 runs (5 for runs over 1 s). The output of every command is byte-identical across all variants.

What was wrong with parts (type, tool_name, message_hash). Without sqlite_stat1, SQLite prefers its type = ? prefix over idx_parts_message_hash_position:

  • _part_ids() (message_hash in (...) and type = ?, three calls per listed turn) then reads every part of that type instead of one message's parts: llm logs list -n 20 went from 204.7 ms to 362.9 ms at 50x.
  • the message_tree view looks up tools per message with (type=? AND tool_name>?): select * from message_tree went from 1.7 s to 75.3 s at 50x (10x: 0.32 s to 3.3 s).

The branch now uses the partial index from the description: parts (tool_name, message_hash) where type = 'tool_result'. Only queries that spell out type = 'tool_result' can use it - the --tools/-T clause and message_tree, both checked with EXPLAIN QUERY PLAN - so _part_ids() keeps its plan. It is also 5x smaller (912 KiB at 50x, against 4.4 MiB).

Write path (in 0.37.1, not caused by this PR). The turn_search refresh in LogStore.log reads all of parts for every logged turn: in response_text the planner puts parts in the outer loop (SCAN parts, then an automatic index on om). log_to_db() costs 3.9 ms per response at 1x, 20 ms at 10x and 122 ms at 50x. Making the two joins in response_text a cross join keeps om outermost: 1.9 / 2.2 / 2.4 ms, with the same turn_search rows. The first index version had hidden this (its type = ? seek cut the scan down to the text parts: 14.7 ms at 50x), which is why I put the two-word fix here. Happy to move it into its own PR if you prefer.

In-process medians in ms, 0.37.1 → this PR:

1x 10x 50x
logs list --tools -n 5 23.0 → 13.4 698 → 18.8 16,779 → 47.7
logs list -T Brave_context -n 5 19.9 → 13.2 516 → 22.1 40,208 → 60.6
logs list --cid <legacy id> -n 5 6.8 → 6.0 14.5 → 5.9 57.1 → 5.8
logs list --cid <thread id> -n 5 13.8 → 11.4 35.3 → 11.3 139.9 → 11.3
logs list -c -n 5 21.4 → 19.7 62.4 → 39.1 274.0 → 146.0
load_conversation(None) (prompt -c) 8.8 → 5.9 31.7 → 6.0 139.2 → 5.9
logs list -n 20 42.7 → 44.7 113.8 → 116.5 204.7 → 208.9
log_to_db() per response 3.9 → 1.9 20.1 → 2.2 121.6 → 2.4
select * from message_tree 321 → 322 1,729 → 1,710

logs list -n 20 is unchanged: its SQL time is identical, and the same code against the same indexes varies by 2-3 ms between runs.

End to end at 50x with hyperfine (llm --version alone takes 1.20 s):

Command 0.37.1 this PR
llm logs list --tools -n 5 17.9 s 1.24 s
llm logs list -T Brave_context -n 5 41.5 s 1.26 s
llm -m echo hi (one logged prompt) 1.34 s 1.22 s

The five indexes add 2.1 MiB at 50x (0.24% of the file). m028 takes 9 ms on my database and 204 ms at 50x.

p.s. created with help of Opus-5.5. Reviewed and used by me.

@rdslw rdslw changed the title Speed up llm logs filters, prompt -c and logging on large databases Speed up llm logs filters, prompt -c and logging on large^H^H^Hnormal after few months :) databases Nov 5, 2026

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant