Two years of query logs, read once

The slow query log has been enabled since 2019 and rotating since, which means two years of compressed evidence sitting on a disk. Nobody had aggregated it, so every piece of performance work in that period was prompted by a complaint rather than by the data.

The symptom

$ ls /var/log/mysql/slow-*.log.gz | wc -l
104
$ du -sh /var/log/mysql/
  8.4G

$ ./bin/perf-work-log --since=2023-06 --field=trigger 
  | sort | uniq -c
     11 a support ticket
      6 somebody noticed a graph
      4 a load test before a launch
      1 the slow log

One piece of performance work in two years prompted by the log that exists to prompt performance work. Everything else came from a symptom that had already reached a person, which means the work was always reactive and always on whichever query happened to annoy somebody.

Why it happens

A log is evidence and reading it is a project nobody schedules, because there is no moment at which it becomes urgent. It accumulates value continuously and demands attention never.

The fix

Normalising two years into shapes

$ zcat /var/log/mysql/slow-*.log.gz | 
    pt-query-digest --limit 30 --order-by Query_time:sum 
    > /tmp/digest.txt

# 41 minutes of CPU, and the whole exercise

$ head -18 /tmp/digest.txt
# Profile
# Rank Query ID  Response time   Calls    R/Call  Item
# ==== ========= =============== ======== ======= =====
#    1 0x8C1F4A7 41208s  22.1%   412884   0.0998  SELECT orders
#    2 0x4A7E8C1 38104s  20.4%       11 3464.0000 SELECT orders JOIN order_lines
#    3 0x9B2D0E6 22884s  12.3%    88204   0.2594  SELECT customers
#    4 0x3F5C7B9 18102s   9.7%  1204882   0.0150  SELECT settings
#   ...
# eleven shapes account for 80.2% of the total.

Ranking by total time rather than by per-call time is what makes the output actionable, and it puts a hundred-millisecond query called four hundred thousand times above a fifty-minute report run eleven times. Both need attention for different reasons, and the same list sorted by per-call time would have produced a completely different afternoon.

The query that runs four million times

rank 4: a settings lookup, by key.

  calls        1,204,882 a month
  per call     15ms
  total        5 hours a month

what it is: a middleware reading one setting per
request, in a loop over up to twenty settings.

what it should be: one query per request for all keys,
or a cached array with an explicit invalidation.

the fix is not making the query faster. it is making it
happen once.

// before: 20 queries per request, each 15ms
foreach (self::REQUIRED as $key) {
    $this->values[$key] = $this->repository->get($key);
}

// after: one query, and a request-scoped cache
$this->values = $this->repository->getMany(self::REQUIRED);

The query that runs eleven times

rank 2: the monthly reconciliation report.

  calls        11 a month
  per call     3,464 seconds — 58 minutes
  total        10.6 hours a month

and what it does while it runs: holds a read view open
for an hour, which is the undo log growth that shows up
as a history list length nobody looks at.

fixing it made the report faster and, more importantly,
stopped it affecting everything else.

A report that runs eleven times a month is easy to dismiss and its cost is not in its own duration — a fifty-eight minute read view means an hour of undo records the purge thread cannot clear, which slows every write on the instance. The per-call number is the visible cost and the concurrency effect is the expensive one.

What was done, in total

  4 indexes added
      one covering index for the reconciliation report
      three composite indexes with the column order
        corrected

  1 query rewritten
      a correlated subquery that the optimiser was
      executing per row, expressed as a join

  1 report moved to a schedule
      it now runs against yesterday's data at 03:00
      and writes a summary table. the interactive
      version reads the table.

  1 middleware fixed
      the settings loop

total: two days.

Making it repeatable

on:
  schedule: [{ cron: '0 6 1 * *' }]   # the first of the month

jobs:
  digest:
    steps:
      - run: |
          ssh db-1 'zcat /var/log/mysql/slow-*.log.gz' 
            | pt-query-digest --limit 20 --order-by Query_time:sum 
            > digest.txt

          ./bin/digest-diff digest.txt digest-previous.txt 
            >> "$GITHUB_STEP_SUMMARY"

The diff against the previous month is what makes this readable — a ranked list every month is a list nobody opens, and “a query that was not in the top twenty last month is now rank 4” is a sentence that gets acted on. It has fired twice since June, both times on a query added by a new feature.

Verifying it worked

# the same aggregation, one month later
$ zcat /var/log/mysql/slow-2025-07*.log.gz | 
    pt-query-digest --limit 5 --order-by Query_time:sum | head -12
#    1 0x9B2D0E6  4,102s  31.1%   88204  0.0465  SELECT customers
#    2 0x1E3A5C7  1,880s  14.3%  412884  0.0045  SELECT orders
#   ...

# total slow-log time, month over month
  before  186,204s
  after    13,208s        # -93%

# and the history list length, which nobody had graphed
  peak before  4,128,104
  peak after      88,204

The history list peak dropping by a factor of forty-six is the change nobody would have looked for, and it is the one that affects every write on the instance. It came entirely from moving the monthly report to a schedule, which was not the most obvious item on the list.

What this costs

An exercise that will need repeating and would not have been, which is why the monthly job exists — and the monthly job is a report somebody has to read. The diff format is the only reason it has been read twice, and a report that is read twice in three months is not obviously a habit.

The 8.4 GB of logs also has a retention nobody had set. Two years of slow query logs is genuinely useful for exactly this exercise and is otherwise a disk that fills, and the rotation is now capped at twelve months — which is a decision that makes the next two-year retrospective impossible and was made deliberately.