Add slow-query log analysis tools (psycodict.slowlog) - #102
Merged
Conversation
roed-math
force-pushed
the
slowlog-analysis
branch
from
July 21, 2026 06:39
f3fa3cf to
cc81ed7
Compare
Tools for the 11.9GB of slow-query logs discussed in LMFDB/lmfdb#6418: parse_slow_log streams the records out of a log written via the slowlogfile option (the colored "ran in" lines, their "Replicate with db.<table>.analyze(...)" hints, the pre-2019 uncolored era, "Search iterator" lines, and multi-line SQL, with unrecognized lines counted and skipped); slow_query_report groups the queries by shape -- normalize_query strips numbers, quoted strings, ARRAY contents and IN/ANY lists, keeping jsonb paths -- and reports per-shape counts and durations, overall percentiles, and a threshold table showing how many lines each candidate slowcutoff would have kept, addressing the issue's first goal directly. Each top shape also carries heuristic suggestions for the issue's second goal: given a db, the columns in WHERE equality/range constraints and the leading ORDER BY column are checked against meta_indexes (via list_indexes) and a create_index call is suggested when no index leads with them; containment operators (@>, <@, &&) suggest a GIN index; leading-wildcard LIKEs and equality on jsonb paths get db-independent notes. db.show_slow_report(logfile) prints the report. The tests generate a real log by pointing a Configuration with slowcutoff = 0 at a temporary file and running searches against a small table, then check parsing, grouping, threshold consistency, and that an index suggestion for an unindexed column disappears once the index is created; a synthetic file covers the older formats. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…mple retention, atomic example/replicate
- Iterator-line query dicts are normalized by a new normalize_dict_query,
which keeps dictionary keys and $-operators (the structure) while still
collapsing values, so {'n': {'$gte': 5}} and {'label': {'$lte': 'z'}} no
longer share a shape; numeric jsonb path components ("data"->0) are now
kept by normalize_query like the string ones already were.
- Index suggestions resolve qualified references ("tbl"."col") against
exactly that table; unqualified columns present on several referenced
tables produce a suggestion naming every candidate instead of silently
using the first match.
- slow_query_report keeps exact numeric aggregates for every shape but
retains the large example/replicate strings only for a candidate set of
~4*top current leaders (lazy min-heap with periodic compaction); the
docstring now states precisely what is bounded and what grows.
- The example and its replicate hint are updated atomically from the same
record, so a slower hintless record clears a stale hint.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The report ranked the top query shapes by total time (the biggest cumulative cost). Add a second ranking by mean time -- the slowest per call, regardless of how often the shape ran -- which surfaces the occasionally-catastrophic queries that a total-time ranking buries under high-frequency ones. slow_query_report now returns shapes_by_mean alongside shapes (the two lists reorder the same per-shape dicts, each finalized once), and show_slow_report prints both sections. Example/replicate strings still follow the total-time retention, so a shape ranked high on mean only by a rare slow call may show its aggregates without an example. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
roed-math
force-pushed
the
slowlog-analysis
branch
from
July 22, 2026 03:07
b32892a to
08916be
Compare
The by-mean ranking is dominated by rare, very slow shapes (often a single call), but example/replicate strings were retained only for the by-total leaders, so those by-mean entries showed their aggregates without a reproducible example. Add a second retention pool keyed on max duration alongside the total-time one (both keys are monotonic per shape, so the existing lazy-heap logic applies to each): a shape keeps its example while it leads by total OR by max, and the max-pool covers exactly the high-per-call shapes the by-mean ranking surfaces. Factored the pool into a _LeaderPool class and use two instances; the candidate set is now up to ~8*top shapes. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Fixes LMFDB/lmfdb#6418.
Stacked on #89 (which stacks on #88); once those merge this reduces to a single commit. Part of an eight-PR wave (with #90–#94 also open); the full thirteen-branch combination was merged and tested locally: 633 passed / 26 skipped, ruff clean, all 23 devmirror tests passing.
New module
psycodict/slowlog.pyfor the 11.9GB-and-growing slow-query logs, addressing both goals in the issue:parse_slow_log: a streaming parser built against what_executeactually emits — the colored<SQL> ran in <t>slines, the pre-2019 uncolored era, theReplicate with db.<t>.analyze(...)hint lines (attached to their record interleaving-safely, since several gunicorn workers append to one file),Search iteratorlines, and multi-line SQL; unparseable lines are counted, not fatal.normalize_querygroups queries by shape: strings/numbers/booleans/ARRAY[...]/IN-and-ANY lists become placeholders, an OR/AND-repeated clause collapses (the jsonb$inexpansion), while identifiers and jsonb path keys survive — so the same search with different constants aggregates under one shape, in both the psycopg2 and psycopg3 renderings.slow_query_report/show_slow_report/db.show_slow_report: per-shape count, total/mean/max durations, tables, the slowest original example and itsanalyze()replication call; overall p50/p90/p99/max; and a threshold table — "a cutoff of X seconds would have kept N records / Y% of volume" — directly answering whether production's slowcutoff should rise (goal 1). Bounded memory via a 3-significant-digit duration histogram; measured ~8 MB/s for a full report, so the real file takes ~25 minutes.dbis passed, WHERE equality/range/ANYcolumns and the leading ORDER BY column are checked againstmeta_indexes, suggestingdb.<t>.create_index([...])only when no index leads with that column (GIN suggested for@>-family operators); db-independent notes for leading-wildcard LIKE (pg_trgm) and jsonb-path equality. Every suggestion states the observation ("appears N times totalling Ys") and the action — no overclaiming.tests/test_slowlog.pythat generate a REAL log (slowcutoff = 0) and verify parsing, grouping, threshold consistency against a re-parse, and the suggestion lifecycle (named index suggestion appears, disappears once the index is created). Branch suite: 550 passed / 26 skipped.Merge-order note: this and the #5900 PR both append methods at the end of
PostgresDatabase; whichever merges second has a trivial append-append conflict — keep both blocks.🤖 Generated with Claude Code