Query Logging and Profiling

You have a benchmark that repeats, and a page somebody has timed at 120 ms of server time. Something inside that request is spending it. WordPress will tell you what it ran, and MySQL will tell you which statements were slow, and the two answers disagree in a way worth understanding before you optimise anything.

Do all of this on a staging copy. Query logging changes the thing it measures, and on a busy production site it changes it enough to matter. If you only have production, read the section on the slow query log first, because that one is designed to run in production and this one is not.

SAVEQUERIES records a row per query, in memory, until the request ends

WordPress keeps a log of every query it runs, and the only thing stopping it is a constant. Add this to wp-config.php above the line that says /* That's all, stop editing! */:

define( 'SAVEQUERIES', true );

With that defined, wpdb starts a timer before each query and calls log_query() after it, which appends to the public property $wpdb->queries. Each entry is a five element array, and the field order is not obvious from reading it, so keep this table next to you:

The time in [1] wraps the whole call through wpdb, which includes WordPress's own work around the statement. Treat it as a ranking signal between queries, not as MySQL's execution time. When the two disagree, MySQL is right about MySQL.

Two habits keep this from biting. Never leave SAVEQUERIES defined in a production wp-config.php, and when you turn it on for a diagnosis, turn it off when the diagnosis ends. If you need the constant on while you work, put it behind a check for a query parameter or an environment variable so that ordinary traffic does not pay for it.

Read the log the right way round, or you will optimise the wrong query

A raw dump of $wpdb->queries is sorted by execution order and is useless at a glance. Nobody can eyeball four hundred rows and find the expensive one. You need two aggregations, and they answer different questions.

Group identical statements together, normalising the numbers and string literals so that two runs of the same template share a bucket, then sort twice:

• By count to find the query that runs most often. This is how you find an N+1 loop, where a template fetches one row per post.
• By total time to find the query that costs most. This is how you find the one statement that needs an index, or needs not to run at all.

The two lists overlap less than people expect. Here is a real example from the lab, using two deliberately shaped endpoints. The first runs one indexed lookup per post in a loop; the second runs a single query that cannot use an index.

?shapedemo=frequent   4023 queries logged   0.359301 s of query time
  4000x   350.229 ms   97.5%   SELECT meta_value FROM wp_postmeta
                                 WHERE meta_key = '?' AND post_id = N LIMIT N

?shapedemo=expensive    24 queries logged   0.029555 s of query time
     1x    11.774 ms   39.8%   SELECT post_id, meta_key FROM wp_postmeta
                                 WHERE meta_value LIKE '%needle%'

Read those two blocks together. The loop runs 4,000 iterations at 88 microseconds each. Every one of them is fast, every one of them is on an acceptable index, and together they are 97.5% of the query time in that request. The scan runs once, takes 12 ms, and would never be fixed by an index on the loop's pattern if the loop were removed instead.

The frequency list is the one you read first, because a query that runs 4,000 times is usually a template that should ask once and cache. The cost list is the one you read second, because a query that runs once and takes 12 ms is a table that needs a different shape, and no amount of caching will fix a full scan you have to run.

The slow query log only sees individual queries, never the total

MySQL has its own logging, and it is a different instrument. It records statements that took longer than long_query_time to execute, which defaults to 10 seconds. Lower it first.

The variables that matter, all settable at runtime with SET GLOBAL or in the server's configuration file:

SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 0.05;
SET GLOBAL log_queries_not_using_indexes = OFF;
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow.log';

Setting it to zero logs everything, which is a way to see the workload once and not a way to run a site. And a warning that costs people an afternoon: if you delete the log file while the server has it open, the server keeps writing to the deleted file and you will stare at a file that never grows. Truncate it instead.

Now the part that surprises people. On the same lab install, with long_query_time set to 0.005, a request that ran 4,023 queries and spent 450 ms of wall clock time produced this many slow log entries:

mysql> SHOW GLOBAL STATUS LIKE 'Slow_queries';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 8     |
+---------------+-------+

mysql> SHOW GLOBAL STATUS LIKE 'Slow_queries';   -- after 4,023 queries
| Slow_queries  | 8     |

Zero new entries, because every one of those 4,023 statements executed in under 5 ms. The slow query log is per statement. It cannot tell you that a query shape ran 4,000 times, and it cannot tell you that your request spent 350 ms in total doing something individually fast. That is a structural limit of the tool, not a configuration mistake.

So use each log for what it measures. WordPress query logging gives you count and total across a whole request. MySQL's slow log gives you the statements that are individually expensive regardless of who ran them, including work from cron. When the slow log is empty and the site is still slow, the problem is cumulative or it is not in the database at all.

EXPLAIN tells you which index MySQL chose and how much it read

Once a query is on your cost list, the next question is what MySQL did with it. EXPLAIN answers that without running the query. Take a statement you recognise from a WordPress log, such as the meta scan above, and prefix it:

EXPLAIN SELECT post_id, meta_key
FROM wp_postmeta
WHERE meta_value LIKE '%needle%';

+----+-------------+-------------+------------+------+---------------+------+---------+------+------+----------+-------------+
| id | select_type | table       | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------------+------------+------+---------------+------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | wp_postmeta | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 4203 |    11.11 | Using where |
+----+-------------+-------------+------------+------+---------------+------+---------+------+------+----------+-------------+

Four columns carry most of the information. type is the access method, and ALL means a full table scan: MySQL read every row. key is the index it actually used, and NULL here means none. rows is its estimate of how many rows it had to examine, which is the number to compare against the number of rows you wanted. Extra carries the warnings, and Using filesort or Using temporary in it means MySQL is doing work after reading the rows, usually because the sort or the grouping had no index to follow.

The same statement with a usable index looks different in the two columns that matter:

EXPLAIN SELECT post_id FROM wp_postmeta WHERE meta_key = 'campaign_source';

| type | possible_keys | key      | rows | Extra       |
| ref  | meta_key      | meta_key |    1 | Using where |

That is why the distinction from earlier matters. WordPress's default schema gives wp_postmeta an index on meta_key and an index on post_id. It has no practical index on meta_value, which is a longtext column, so any query that filters on the value scans the whole table. If you have ever wondered why a plugin's search feature is slow on a large site, that is the reason, and no amount of object caching fixes the first uncached run.

Classic EXPLAIN gives you estimates. Newer MySQL versions also support EXPLAIN ANALYZE, which runs the statement and reports actual rows and actual time alongside the estimate. That is the version to reach for when the estimate looks fine and the query is still slow, because the gap between estimated and actual rows is usually the whole story:

-> Filter: (wp_postmeta.meta_value like '%needle%')  (cost=425 rows=467)
    (actual time=5.07..5.07 rows=1 loops=1)
    -> Table scan on wp_postmeta  (cost=425 rows=4203)
        (actual time=0.0337..4.23 rows=4203 loops=1)

Both EXPLAIN and EXPLAIN ANALYZE work the same way from a WordPress context: the optimiser does not care that WordPress generated the statement, so run it yourself against the database. What you cannot do is run it inside a request without changing the request. Profile first, then take the SQL out and examine it on its own.

type of index is the middle case worth recognising: an index was used, but it was read end to end, so it costs almost what a full table scan costs. Running EXPLAIN on the priming query from the lab shows exactly that, and it is why the statement is the costliest one in the request even though WP_Query only ran it once:

EXPLAIN SELECT post_id, meta_key, meta_value FROM wp_postmeta
WHERE post_id IN (1,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,25,
26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50)
ORDER BY meta_id ASC;

+----+-------------+-------------+------+---------------+---------+---------+------+------+----------+-------------+
| id | select_type | table       | type | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------------+------+---------------+---------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | wp_postmeta | index| post_id       | PRIMARY | 8       | NULL | 7407 |    60.52 | Using where |
+----+-------------+-------------+------+---------------+---------+---------+------+------+----------+-------------+

Seven thousand four hundred and seven rows examined on a table with 7,329 rows, to return the meta for the posts in the list, using an index on post_id that the optimiser chose to read end to end instead of seeking. That is the kind of finding that turns a template argument into a database argument, and you only get it by looking at the plan.

The limitation you should state out loud

Every instrument here changes what it measures. SAVEQUERIES adds memory proportional to query count and slows the request. The slow query log is cheaper but still writes per qualifying statement, and log_queries_not_using_indexes on a busy site can produce more log than traffic. EXPLAIN ANALYZE executes the statement, so on a table being written to at the same time it can block.

None of that makes the numbers useless. It makes them numbers from an instrumented request, which is fine as long as you use them to rank problems against each other and not as your latency baseline. Take the baseline with the instruments off, using the benchmark from lesson 1.

<?php
/**
 * Plugin Name: Query Shape Log
 */

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

    if ( ! defined( 'SAVEQUERIES' ) || ! SAVEQUERIES ) {
        return;
    }

    $shapes = array();

    foreach ( (array) $wpdb->queries as $entry ) {
        $sql = preg_replace( '/\s+/', ' ', $entry[0] );
        $sql = preg_replace( "/'[^']*'/", "'?'", $sql );
        $sql = preg_replace( '/\b\d+\b/', 'N', $sql );

        if ( ! isset( $shapes[ $sql ] ) ) {
            $shapes[ $sql ] = array( 'count' => 0, 'time' => 0.0 );
        }

        ++$shapes[ $sql ]['count'];
        $shapes[ $sql ]['time'] += (float) $entry[1];
    }

    uasort( $shapes, fn( $a, $b ) => $b['time'] <=> $a['time'] );

    file_put_contents(
        WP_CONTENT_DIR . '/uploads/query-shapes.json',
        wp_json_encode( $shapes, JSON_PRETTY_PRINT )
    );
}, 9999 );

SELECT post_id, meta_key, meta_value FROM wp_postmeta
WHERE post_id IN (23,22,21,20,19,18,17,16,15,14) ORDER BY meta_id ASC
   1x   13.701 ms   42.5% of query time in that request

EXPLAIN SELECT post_id, meta_key, meta_value FROM wp_postmeta
WHERE post_id IN (23,22,21,20,19,18,17,16,15,14) ORDER BY meta_id ASC;

EXPLAIN SELECT option_value FROM wp_options WHERE option_name = 'blogname' LIMIT 1;