MySQL Performance Schema: Finding the Most Expensive Statements

The slow query log misses the query that runs in 3 ms but 4,000 times a second and quietly eats half the CPU. That's the one that usually turns out to be the problem, and Performance Schema is how I find it. It aggregates every statement by normalized form (the "digest") and keeps totals for latency, rows examined, temp tables, sorts and full scans since startup. On 5.7 and 8.0 it's on by default, and the sys schema gives you readable views.

This is my routine on a server I've never seen before. It needs performance_schema = ON, the sys schema (default since 5.7.7; on an upgraded server run mysql_upgrade if SHOW DATABASES doesn't list it), and an account with SELECT on both plus PROCESS.

Is statement instrumentation on?

SELECT * FROM performance_schema.setup_consumers WHERE name LIKE 'events_statements%';
SELECT * FROM performance_schema.setup_instruments WHERE name LIKE 'statement/sql/%' AND enabled = 'NO';

events_statements_current, events_statements_history and the digest consumer should be YES. If someone disabled them:

UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name LIKE 'events_statements%';
UPDATE performance_schema.setup_instruments SET enabled = 'YES', timed = 'YES' WHERE name LIKE 'statement/%';

These changes are lost on restart; make them permanent in my.cnf with performance-schema-consumer-events-statements-history = ON and performance-schema-instrument = 'statement/%=ON'.

Top statements by total time

The raw table is events_statements_summary_by_digest. Total latency is what matters most for server load:

SELECT schema_name, digest_text, count_star,
       ROUND(sum_timer_wait/1e12, 2) AS total_s,
       ROUND(avg_timer_wait/1e9, 2)  AS avg_ms,
       sum_rows_examined, sum_rows_sent,
       sum_created_tmp_disk_tables, sum_sort_rows, sum_no_index_used
FROM performance_schema.events_statements_summary_by_digest
ORDER BY sum_timer_wait DESC
LIMIT 10;

Timers are in picoseconds, hence the division. digest_text shows the statement with literals replaced by ?, so SELECT * FROM orders WHERE id = 5 and ... id = 99 are one row.

The sys views are nicer

I rarely type the raw query above any more. sys.statement_analysis is the same data with units already converted:

SELECT query, db, exec_count, total_latency, avg_latency, rows_examined_avg, tmp_disk_tables, full_scan
FROM sys.statement_analysis
ORDER BY total_latency DESC
LIMIT 10;

Other views answer specific questions:

SELECT * FROM sys.statements_with_full_table_scans LIMIT 10;
SELECT * FROM sys.statements_with_temp_tables LIMIT 10;
SELECT * FROM sys.statements_with_sorting LIMIT 10;
SELECT * FROM sys.statements_with_errors_or_warnings LIMIT 10;

The x$ versions (sys.x$statement_analysis) return raw numbers instead of formatted strings, which is what you want when feeding a monitoring system.

Getting a real example of a digest

The digest text has ? placeholders. To see a real execution with real values, look in the history tables while the statement is running frequently:

SELECT sql_text, ROUND(timer_wait/1e9,2) AS ms, rows_examined
FROM performance_schema.events_statements_history_long
WHERE digest = '9d0eb7a9f8e1a0f1...'      -- the DIGEST column from the digest query
ORDER BY timer_wait DESC LIMIT 5;

events_statements_history_long is off by default; enable its consumer the same way as above, and only for a short while. It keeps the last 10,000 statements server-wide, which on a busy server is a few seconds of history – enough to catch a frequent query.

Measure a window

The summary accumulates since startup, so a batch job from three weeks ago can dominate the list. To measure a specific period, truncate and wait:

TRUNCATE performance_schema.events_statements_summary_by_digest;
-- wait 15 minutes of representative load
SELECT query, exec_count, total_latency FROM sys.statement_analysis ORDER BY total_latency DESC LIMIT 10;

Truncating loses history, so do this when you actually intend to compare before and after a change. On 8.0 sys.ps_truncate_all_tables(FALSE) resets everything at once.

Who is running it?

Once you have the digest, find the accounts and hosts:

SELECT user, host, count_star, ROUND(sum_timer_wait/1e12,1) AS total_s
FROM performance_schema.events_statements_summary_by_account_by_event_name
WHERE event_name = 'statement/sql/select'
ORDER BY sum_timer_wait DESC LIMIT 10;

And for the current moment, sys.session is a nicer SHOW PROCESSLIST with current statement latency and the last wait event per connection.

Closing the loop

Take the top query, run EXPLAIN on a real example, fix the index or the query, and then compare avg_latency and rows_examined_avg for that digest a day later. sys.statement_analysis also has a first_seen/last_seen pair so you can confirm the new version of the query is what is being executed now.

When the numbers look wrong

• sys.statement_analysis is empty or only shows your own queries – The digest consumer is off, or performance_schema_digests_size (default 10000) is full and new digests are being lumped into a single row with digest_text = NULL. Raise the setting in my.cnf and restart.
• ERROR 1142 (42000): SELECT command denied to user 'monitor'@'%' for table 'events_statements_summary_by_digest' – Grant SELECT ON performance_schema.* and SELECT ON sys.*; PROCESS is required for the sys.session view.
• Latency numbers look impossibly large – You are reading picoseconds; divide by 1e12 for seconds or use the sys views.
• A digest shows sum_no_index_used greater than zero but EXPLAIN uses an index – The digest groups queries with different literal types; one variant (for example comparing a string to an integer column) prevents index use. Pull examples from the history table to find it.

The top-ten-by-total-latency query is the first thing I run on any server I'm asked to look at.