Why Your Slow-Query Log Is Lying to You (a Little)

You’ve done the obvious work. You pulled a slow-query log off production, found the worst offenders, added indexes, rewrote a couple of queries, and shipped it. Response times improved. Everyone’s happy.

And yet — the site is still slow, somewhere, in a way nobody can quite pin down. An editor complains the block editor takes forever to open on the homepage. A field engineer notices the sitemap occasionally times out. Nothing shows up in the log anymore, because the log only captures what happens to run while it’s capturing.

This is the part of performance work that a log sample structurally can’t do for you: tell you what it didn’t see.

TL;DR: Production slow-query logs miss rarely-hit paths, cache-state-dependent queries, and anything that regressed after the log was pulled. Fix: an opt-in SAVEQUERIES-based profiler you switch on for one debugging session and crawl the site with deliberately, front end and back end. Along the way: a before/after comparison on an unwarmed cache can look like a 4-5x win that isn’t real — always measure at least three warm runs on both sides before trusting a performance number.

What Does a Slow-Query Log Sample Actually Miss?

A production slow-query log is a snapshot, not a map. It’s a good starting point — it tells you what’s definitely slow, definitely hit, definitely worth fixing. But it under-represents three categories of problem, systematically:

Rarely-hit paths. A log capturing 15 minutes of production traffic will faithfully record every slow homepage query, because the homepage gets hit constantly. It will very likely not capture the query that runs when an editor opens the block editor on a specific post type, because that happens a handful of times an hour, not a handful of times a second. The query can be catastrophically slow and still never appear in your sample.

Cache-state dependence. Some queries are fast on a warm cache and slow on a cold one — object cache, query cache, opcode cache, even the OS’s own filesystem cache all shape what "slow" means at the moment you happened to be looking. A log sample tells you nothing about which state you caught it in.

Anything that changed since the log was pulled. Obvious, but easy to forget: a regression introduced last week isn’t in a log you pulled two months ago.

None of this is a knock on log-based analysis — it’s just an argument for not stopping there.

How Do You Find What the Log Can’t Show You?

The fix is almost embarrassingly direct: stop waiting for production traffic to stumble into the slow path, and go visit it yourself, on a environment where you’re allowed to instrument every request.

The tool for this is one you already have half-built into WordPress: SAVEQUERIES. Normally you’d define it as a constant in wp-config.php before WordPress boots, and every query for every request gets recorded, with timing, into $wpdb->queries. The catch is that if you turn this on globally, you’re adding overhead to every single request, on every environment, forever — not something you want to leave running.

The trick that makes this practical is that wpdb checks SAVEQUERIES live, per query, not once at construction time. That means you can define it much later than wp-config.php — from a lightweight mu-plugin, gated behind an explicit opt-in — and still capture the entire request’s query log:

<?php
/**
 * Opt-in slow-query profiler. Inert unless explicitly enabled — a stray
 * copy of this left in mu-plugins after a debugging session should not
 * silently tax every future request.
 */
if ( ! defined( 'SLOW_QUERY_PROFILER_ENABLED' ) || ! SLOW_QUERY_PROFILER_ENABLED ) {
    return;
}

if ( ! defined( 'SAVEQUERIES' ) ) {
    define( 'SAVEQUERIES', true );
}

add_action( 'shutdown', function () {
    global $wpdb;

    if ( empty( $wpdb->queries ) ) {
        return;
    }

    $threshold = 0.05; // seconds
    $lines     = [];

    foreach ( $wpdb->queries as $query ) {
        [ $sql, $duration ] = $query;

        if ( $duration < $threshold ) {
            continue;
        }

        $context = defined( 'WP_CLI' ) && WP_CLI
            ? 'wp-cli'
            : ( $_SERVER['REQUEST_URI'] ?? 'unknown' );

        $lines[] = sprintf(
            "%.4f\t%s\t%s\n",
            $duration,
            $context,
            preg_replace( '/\s+/', ' ', trim( $sql ) )
        );
    }

    if ( ! empty( $lines ) ) {
        file_put_contents(
            '/tmp/slow-query-profiler.log',
            implode( '', $lines ),
            FILE_APPEND | LOCK_EX
        );
    }
}, PHP_INT_MAX );

That’s genuinely most of it. A few things worth calling out:

  • It’s opt-in and inert by default. The whole point is that you drop this in for one debugging session and can safely forget to remove it for a day without consequence.
  • It hooks shutdown, not wp_footer or similar. You want this to run for every kind of request — REST API calls, admin-ajax, WP-CLI commands — not just full page renders.
  • The threshold matters. Set it too low and you’ll drown in noise; too high and you’ll miss the "merely bad" queries that add up. Start around 50ms and adjust.

From there, wrap a few WP-CLI commands around reading and clearing that log file, and you have a reusable tool: status to check it’s on, clear to start a fresh session, report to print the results sorted worst-first.

Where Should You Point the Profiler?

Once it’s running, go crawl the site like a slightly obsessive user. A reasonable checklist:

Front end: the homepage, a few representative content pages across different templates, category/tag archives, search (including empty-result search), any sitemap endpoints, RSS feeds, and any REST API calls the front end actually makes (check your browser’s network tab on a real page load).

Back end, logged in: the post list screens — including with a search term and a taxonomy filter applied, since list-table queries often add extra clauses under those conditions — the block editor on a representative post, and any custom admin screens the site ships.

Do this against a local or staging environment with a full-size, representative dataset, not production. SAVEQUERIES and arbitrary code execution (wp eval, direct wp-config.php edits) are exactly the kind of thing you don’t want to run against live traffic, and most managed hosting platforms will actively block you from doing so on anything but a local development environment anyway.

What Measurement Mistake Almost Shipped a Bad Fix?

Here’s where it gets uncomfortable. Partway through a crawl like this, I found a candidate: a taxonomy archive page whose underlying query used SELECT DISTINCT where a plain GROUP BY looked like it should be equivalent and cheaper. I made the change, ran it once before and once after, and got a number that looked fantastic — something like a 4-5x improvement.

It wasn’t real.

The "before" measurement was a cold run; the "after" measurement benefited from every cache in the stack already being warm from the first request. A single before/after comparison on a system with multiple layers of caching isn’t a measurement — it’s a coin flip that happens to land the way you were hoping.

I caught it, by luck more than discipline, by re-running the "before" query a second time and watching the number drop to match the "after" figure almost exactly. No code had changed between those two runs. The cache had.

What’s the Rule for Trusting a Performance Number?

Since then, the rule is simple and non-negotiable: measure at least three repeated runs, warm, on both sides of a change, before trusting a performance number.

Concretely:

  1. Run the query (or hit the page) two or three times before your change, discard the first run as cache warm-up, and record the rest.
  2. Make the change.
  3. Run it two or three times after, again discarding the first run.
  4. Only claim an improvement if the warm "after" runs are consistently faster than the warm "before" runs — not just faster than a single unwarmed "before" sample.

There’s a second, sneakier version of this trap worth knowing about: a plugin that caches its own output — a generated XML sitemap, a rendered fragment — independent of how fast the underlying query is. Hit the same cached page twice and it’ll look instant regardless of whether you fixed anything at the database layer. If there’s an output cache in play, verify the fix directly against the database (EXPLAIN ANALYZE, or your query profiler with the output cache bypassed) rather than trusting HTTP timing alone.

What Did Crawling Actually Find?

Applying this — the profiler, the crawl checklist, and the "measure three times, warm" discipline — on a WordPress VIP-style multisite network of regional news sites turned up something the original slow-query log had never shown at all: a sitemap endpoint quietly taking nine to eleven seconds on one of the larger sites, every single time, cache-warm included.

That one turned into a genuinely interesting debugging story — a hardcoded index hint buried in third-party plugin core, silently sorting on the wrong column for tens of thousands of rows. That’s the next post.