Ranking by share of total database time instead of slowest single query is the bit I wish we had a few weeks ago. Our site started hanging and no query looked bad on its own: it was one ordinary listing query fired thousands of times by crawlers with odd filter combinations, and we only found it from stack dumps of the stuck workers. We run SQLite, so I can't point Culprit at it yet. Does it group statements by normalized shape, so the same query with different parameters adds up into one finding?
Yes. On PostgreSQL, MySQL/MariaDB and SQL Server, Culprit works from the engine's own normalized statements, so the same query with different values adds up into one statement, ranked by its share of database time, with no changes to your app.
SQLite support is coming. Point Culprit at your .db file and it opens it read-only: missing or duplicate indexes, planner statistics, free space, and the plan of any statement you give it, including whether it reads the whole table. That listing query would have shown a full scan.
SQLite itself doesn't record which statements ran or for how long, so to rank by total time Culprit can also read a query log your framework may already write: Rails' log, or Django's database log at DEBUG. It groups repeats of the same shape, so the listing query with different filter values adds up into one, ranks shapes by total time, and plans each one. Different filter combinations are separate shapes, listed side by side. Either way, no code changes. Which framework do you run?
@cristipufu neither, sadly. It's FastAPI on plain sqlite3, no ORM, so nothing writes a query log today. The cheap fix on our side is a small wrapper around execute that logs each statement with its duration. If we go that way, what line format would Culprit read, or is a Django-style log the safest thing to imitate?
SQLite support just shipped (0.3.0, preview). No need to imitate Django: Culprit reads a simple JSON-lines log, one query per line, with sql, ms and at. Log the SQL with its ? placeholders, time each query through the fetch rather than just execute(), and name the file after your database (app.db → app.log) so Culprit picks it up automatically. Repeats of the same query add up and get ranked by total time. Short guide with the wrapper: https://github.com/cristipufu/culprit-sql-studio/blob/main/docs/sqlite.md#logging-queries-yourself
@cristipufu that was quick. Timing through the fetch is the detail I would have missed, our slow part is reading the rows, not sending the query. One thing before I wire it in: we have a web process and a background worker writing to the same .db, so two writers into one app.log. Is interleaved output fine, or better one log per process?
Interleaved is fine, and keep one shared app.log. Culprit reads one log per database, so with a log per process, one process's queries would be left out. Line order doesn't matter: each statement's time is summed whatever order its lines arrive in, and the period comes from the earliest and latest at.
The one thing to avoid is two processes writing pieces of the same line. Python's buffered file can split a long line into two writes, so write each line with a single os.write on a file opened for appending:
fd = os.open("app.log", os.O_WRONLY | os.O_APPEND | os.O_CREAT, 0o644)
os.write(fd, (json.dumps(entry) + "\n").encode())
A mangled line is skipped anyway, so the worst case is one missing statement.
Also plan for the file's size: it grows by a line per statement, roughly 30 MB a day at 100K statements, and Culprit reads the whole file on each scan. Rotate it daily with logrotate's copytruncate, so both processes keep writing to app.log without a restart. Culprit then ranks what has run since the last rotation.