MonPG Engineering avatar MonPG Engineering Engineering Team MariaDB 6 min read

MariaDB Slow Query Log Triage: From long_query_time to a Digest You Can Act On

After the third 'the site felt slow around lunch' report in a month, we stopped arguing about whether it happened and turned on the slow query log properly. The first digest took eleven minutes to produce and named one query responsible for 61% of all slow time.

MariaDB

The reports were maddeningly soft: the site felt slow around lunch, three weeks running, never during any deploy, never during any alert. Latency percentiles showed nothing at the minute granularity our dashboards aggregated to. Someone proposed a caching layer. Someone else proposed upgrading the instance class. What settled it was the oldest observability tool MariaDB ships: the slow query log, configured with intent instead of the default on-for-a-week-then-forgotten posture. We enabled it at a quarter-second threshold with query plan verbosity for a single lunch window, digested the output, and eleven minutes later had a named suspect: a category-listing query with a LIKE and an implicit cast, running 400 times an hour at 900 milliseconds each, responsible for 61% of all slow query time. Total remediation was one expression index and a query rewrite. The caching layer died in committee, unmourned.

The slow log is not a fire-and-forget toggle; it is a measurement campaign with an enable phase, a capture phase, and a digestion phase, and most teams do the first badly and skip the third entirely. This is the workflow we now run quarterly, incident or not.

How do you enable the slow log without drowning in it?

The two mistakes are logging too little and logging everything forever. Logging too little means leaving long_query_time at its default of ten seconds, at which point you capture only catastrophes and learn nothing about the quarter-second queries that dominate real user pain. Logging everything forever means setting long_query_time to zero on a busy server and discovering that the log itself becomes the I/O problem — we once generated 40 GB of slow log in a weekend on a reporting replica, which is a fine way to meet your disk-alerting infrastructure. The posture that works: pick a threshold that captures the tail you actually care about — 0.25 seconds for our OLTP primaries, 2 seconds for reporting replicas — write to a file rather than the mysql.slow_log table, because table output adds write load exactly when the server is busiest, and scope the capture to a defined window with a calendar reminder to turn it back down:

-- capture posture for an OLTP primary: quarter-second tail
SET GLOBAL slow_query_log = ON;
SET GLOBAL log_output = 'FILE';
SET GLOBAL long_query_time = 0.25;
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow-campaign.log';

-- sample instead of drowning on very hot servers:
-- log every 10th slow query (MariaDB-specific)
SET GLOBAL log_slow_rate_limit = 10;

-- and when the window closes, restore the boring defaults
SET GLOBAL long_query_time = 2;
SET GLOBAL log_slow_rate_limit = 1;

log_slow_rate_limit deserves its own sentence because it is the feature people reach for sampling in application code to get: it logs one in N slow statements, which keeps the file tractable on a server where the slow tail is still thousands of queries a minute, at the cost of needing to remember that your digest counts are now a sample. For a first pass on an unfamiliar server I skip it — one quarter-second window at full capture has never yet hurt us — and I bring it in only when the capture window has to run for days.

Which knobs decide what actually gets logged?

Threshold alone tells you a query was slow; verbosity tells you why. MariaDB’s log_slow_verbosity is where the log earns its keep, and the value you want for triage is query_plan, which annotates each entry with the optimizer’s high-level decisions — full table scans, full joins, the number of examined rows — so the digest can aggregate not just which queries were slow but which categories of bad plan drove them. min_examined_row_limit is the companion knob: statements that examine fewer rows than the limit are skipped regardless of time, which filters out the sub-millisecond primary-key lookups that would otherwise flood a low-threshold capture. log_queries_not_using_indexes is the trap to avoid on hot servers — it logs every index-less query even fast ones, and on a schema with legitimate small lookup tables it multiplies log volume by an order of magnitude while teaching you nothing:

-- the verbosity that makes digests actionable
SET GLOBAL log_slow_verbosity = 'query_plan';

-- skip statements that barely examined anything
SET GLOBAL min_examined_row_limit = 1000;

-- see the whole posture before you start the clock
SHOW GLOBAL VARIABLES WHERE Variable_name IN (
  'slow_query_log', 'long_query_time', 'log_output',
  'log_slow_verbosity', 'log_slow_filter',
  'min_examined_row_limit', 'log_slow_rate_limit'
);

One honest warning about EXPLAIN annotations: the log tells you what the optimizer chose, not what it should have chosen, and the fix path runs through reading actual execution plans — the workflow in the ANALYZE FORMAT=JSON notes is the natural next step once the digest names its targets, because ANALYZE shows you the plan the query actually executed with real row counts, not the planner’s estimate.

How do you turn 300,000 log lines into a fix list?

You do not read a slow log; you digest it. pt-query-digest from Percona Toolkit works fine against MariaDB slow logs and has survived every toolchain migration we have thrown at it. The digest groups statements by fingerprint — the query with literals and whitespace stripped — so 400 executions of the same category query collapse into one ranked entry, and the ranking that matters is total time, not average time: a 900-millisecond query running 400 times an hour outranks a ten-second query running twice a day, and the lunch-window mystery is almost always the former:

-- the one-liner that ends the meeting
-- pt-query-digest /var/log/mysql/slow-campaign.log --   --order-by Query_time:sum --limit 15 > digest.txt

-- sanity-check the sample inside SQL while it runs:
SELECT * FROM mysql.slow_log ORDER BY query_time DESC LIMIT 5;
-- (only when log_output=TABLE; on file captures, the digest is truth)

The triage discipline that made this repeatable for us is a one-page report per campaign: top five fingerprints by total time, rows examined versus rows returned for each, the plan annotation from query_plan verbosity, and a verdict column with exactly three allowed values — index, rewrite, or accept. Accept is a legitimate verdict: some reporting queries are slow because they move a lot of data, and the correct fix is moving them to the replica or fencing them with a statement timeout, the pattern from the max_statement_time notes. The other discipline is statistical honesty: one capture window is a hypothesis, not a conclusion, and we re-run the digest after each fix ships to confirm the fingerprint actually left the ranking. Our category query dropped from 61% of slow time to unmeasurable, and the second campaign found the next suspect — an unindexed date-range scan on an audit table — which is the real lesson: the digest is not an incident tool, it is a standing quarterly ritual, and the marginal cost after the first run is an afternoon.

Where MonPG fits

For MonPG product capabilities and setup information, see the MariaDB monitoring page. Use the diagnostics in this article to identify the measurements and operational checks your deployment needs.

Related documentation