psycodict.slowlog

Tools for analyzing the slow-query logs that psycodict writes.

When a query takes longer than the slowcutoff configured in the [logging] section, PostgresBase._execute appends lines like the following to the file configured as slowlogfile:

2026-07-20 20:19:14,940 - SELECT "label" FROM "curves" WHERE "n" = 5 ORDER BY "n" ran in \x1b[91m 0.35s \x1b[0m
2026-07-20 20:19:14,940 - Replicate with db.curves.analyze({'n': 5}, ['label'], None, 0)

The timing is wrapped in ANSI color escapes, the Replicate with hint line follows the query it describes, and versions of this code from before 2019 wrote ... ran in 0.35s without the color escapes. A query whose inlined values contain newlines spans several physical lines. Search iterators log a third shape (normally only to the console, but captured console output is worth parsing too):

Search iterator for curves {'n': 5} required a total of \x1b[91m0.35s\x1b[0m

The functions here parse such files, group the queries by shape (the query with all constants removed), and produce a report aimed at two questions: would raising slowcutoff shrink the log substantially, and which queries might benefit from an index?

Typical usage:

from psycodict.slowlog import show_slow_report
show_slow_report("slow_queries.log", db=db)  # db optional

or equivalently db.show_slow_report("slow_queries.log"). Nothing here writes to the database: when db is provided, the report reads the indexes recorded in meta_indexes (through table.list_indexes()) to check whether the columns constrained by slow queries are covered.

psycodict.slowlog.parse_slow_log(logfile, stats=None)

Iterate over the records in a slow-query log file.

INPUT:

• logfile – the filename of a slow-query log (as configured by the slowlogfile logging option), or an open file object

• stats – an optional dictionary, updated in place with the keys lines (physical lines read) and unparsed (lines that were not part of any recognized record)

OUTPUT:

An iterator of dictionaries, one per logged query, with keys:

• timestamp – a datetime from the logging prefix (None if absent)

• duration – the logged runtime in seconds, as a float

• query – the SQL that was logged; for search iterator records, the query dictionary as a string

• kind – "query" for ordinary statements, "iterator" for Search iterator records

• table – the table the query was issued against, when the log provides it (from the adjacent Replicate with hint line, or from the search iterator line); otherwise None. A hint is attached only when its table appears in the query, since several processes appending to one log can interleave their lines.

• replicate – the db.<table>.analyze(...) call from the hint line when present, for replaying the query

• lines – the number of physical log lines this record occupies, including its hint line and any continuation lines

Multi-line SQL (inlined values containing newlines) is reassembled. Unrecognized lines are skipped and counted in stats, since a log that has accumulated for years contains lines in formats no longer in use.

psycodict.slowlog.normalize_query(query)

Normalize an SQL query (or a query dictionary rendered as a string) to its shape: literal values are replaced by ? so that queries differing only in their constants compare equal.

• numbers, quoted strings and boolean literals become ? (string literals and numbers directly after the jsonb path operators ->, ->>, #>, #>> are kept, since they select which field or array position is queried rather than which value)

• the contents of ARRAY[...] literals collapse to ARRAY[?]

• comma-separated lists of replaced values, as in IN (1, 2, 3), collapse to (?)

• a clause repeated with OR (or AND), as produced for example by $in on a jsonb column, collapses to a single copy

• runs of whitespace (including newlines) become a single space

Identifiers are left alone, even when they contain digits.

EXAMPLES:

sage: from psycodict.slowlog import normalize_query
sage: normalize_query("SELECT \"a\" FROM \"t\" WHERE \"n\" = 5 AND \"s\" = 'x1' LIMIT 4")
'SELECT "a" FROM "t" WHERE "n" = ? AND "s" = ? LIMIT ?'

psycodict.slowlog.normalize_dict_query(query)

Normalize a query dictionary rendered as a string (the Python repr that Search iterator log lines carry) to its shape.

In a query dictionary the keys – column names and $-operators like $gte – describe the structure of the query, and only the values are data, so normalize_query() (which treats every quoted string as a literal value) would collapse structurally different queries such as {'n': {'$gte': 5}} and {'label': {'$lte': 'z'}} to the same shape. Here a quoted string or a number is kept exactly when it is followed by :, i.e. when it is a dictionary key:

• values (numbers, quoted strings, True/False/None) become ?

• lists and tuples of replaced values collapse: [1, 2, 3] becomes [?], so $in queries group independently of the list length

• runs of whitespace (including newlines) become a single space

EXAMPLES:

sage: from psycodict.slowlog import normalize_dict_query
sage: normalize_dict_query("{'n': {'$gte': 5}, 'label': 'a'}")
"{'n': {'$gte': ?}, 'label': ?}"

psycodict.slowlog.slow_query_report(logfile, top=20, cutoff=None, db=None)

Analyze a slow-query log file, grouping queries by shape.

INPUT:

• logfile – the filename of a slow-query log (as configured by the slowlogfile logging option), or an open file object

• top – the number of query shapes to include in each ranking (there are two: by total time and by mean time)

• cutoff – only consider queries at least this slow (in seconds). This simulates raising slowcutoff: the report shows what the log would have contained with that threshold.

• db – an optional PostgresDatabase. When provided, the suggestions check the columns constrained by each query shape against the indexes recorded in meta_indexes (via list_indexes) for the search tables involved, and suggest create_index calls for constrained columns that no existing index leads with.

OUTPUT:

A dictionary with keys:

• logfile, cutoff – the corresponding inputs

• lines – the number of physical lines in the file

• unparsed – lines that were not part of any recognized record

• records – the number of parsed query records

• skipped – records below cutoff (0 when no cutoff is given); the rest of the report describes the records - skipped others

• total_time – their summed duration in seconds

• percentiles – a dictionary with keys p50, p90, p99 and max. The percentiles are computed from a histogram with 3 significant digits, so they are lower bounds accurate to about 1%; the max is exact.

• thresholds – a list of dictionaries with keys cutoff, records, lines and percent: raising slowcutoff to that value would have logged that many records, occupying that many physical lines, i.e. that percentage of the current line volume. The candidate cutoffs mix a fixed ladder with the observed percentiles.

• shapes – a list of dictionaries, one per query shape, sorted by total time, with keys shape, kind, count, total, mean, max, tables, example (the slowest query retained for this shape; see below), replicate (the hint-line call of that same example record, if it had one) and suggestions (a list of strings; see the module documentation).

• shapes_by_mean – the same kind of list, the top shapes ordered by mean time instead of total time (the two lists overlap and share their dictionaries).

Memory use: the per-shape numeric aggregates (count, total, max, tables and the shape string itself) are exact and are kept for every distinct shape, so that total_time, percentiles, thresholds and the reported aggregates do not depend on top. This dictionary grows with the number of DISTINCT shapes – bounded in practice by the variety of queries the application issues, not by the length of the log. The large per-shape strings (example and replicate), by contrast, are retained only for a bounded candidate set: the current leaders by total time (up to 4 * top shapes) together with the current leaders by max duration (up to another 4 * top), so that both the by-total and the by-mean rankings have reproducible examples. When a shape drops out of both pools its example is discarded, and if it later climbs back the next record of that shape refills it. The example of a reported shape is therefore the slowest of the records that arrived while the shape was retained – normally, but not always, its globally slowest record. Every reported shape has an example, and with top=None all shapes retain theirs.

psycodict.slowlog.show_slow_report(logfile, top=20, cutoff=None, db=None)

Print the report produced by slow_query_report; see its documentation for the inputs.

EXAMPLES:

sage: from psycodict.slowlog import show_slow_report
sage: show_slow_report("slow_queries.log", db=db)  # db optional