Skip to content

CONCEPT Cited by 1 source

Query stage profiling

Query stage profiling is a MySQL diagnostic technique that decomposes a single query execution's wall-clock time into per-stage milliseconds: how much was spent optimising, opening tables, checking permissions, executing, waiting for handler commit, freeing items. It answers the question "my query is slow — slow doing what?"

(Source: sources/2026-04-21-planetscale-identifying-and-profiling-problematic-mysql-queries.)

What it shows vs EXPLAIN ANALYZE

  • EXPLAIN ANALYZE shows per-iterator cost in the execution plan tree — it tells you which operator was expensive.
  • Stage profiling shows per-execution-stage cost in the server lifecycle — it tells you which phase of the server's work was expensive. Two orthogonal views.

If a query's wall-clock is dominated by stage/sql/executing, EXPLAIN ANALYZE is the right next step. If it's dominated by stage/sql/optimizing or lock-wait stages, the fix is elsewhere (stats, lock contention, schema change ordering).

Enablement (three toggles)

PlanetScale's post gives the canonical enablement SQL:

-- 1. Enable instruments (what to measure)
UPDATE performance_schema.setup_instruments
  SET ENABLED = 'YES', TIMED = 'YES';

-- 2. Enable consumers (where to store)
UPDATE performance_schema.setup_consumers
  SET ENABLED = 'YES', TIMES = 'YES';
-- (Note: MySQL column is actually named TIMED, not TIMES;
--  the post has a typo. The column gates timer collection.)

-- 3. Enable history for the principal (who to profile)
INSERT INTO performance_schema.setup_actors
  (HOST, USER, ROLE, ENABLED, HISTORY)
  VALUES ('your_host', 'your_user', '%', 'YES', 'YES');

Selective scoping via setup_actors: flip the default-match row off (WHERE HOST='%' AND USER='%') and insert only the principal you care about, so the profiling tax doesn't hit every session.

Selective stages via setup_instruments:

UPDATE performance_schema.setup_instruments
  SET ENABLED = 'NO', TIMED = 'NO';
UPDATE performance_schema.setup_instruments
  SET ENABLED = 'YES', TIMED = 'YES'
  WHERE NAME LIKE '%stage/%';

The four-step workflow

From the post, verbatim structure:

  1. Capture the thread ID of the connection you'll run the query on:
SET @connection_thread = (
  SELECT thread_id FROM performance_schema.threads
  WHERE PROCESSLIST_ID = CONNECTION_ID() );

  1. Execute the query you want to profile.

  2. Find the statement_id by scanning recent history:

SELECT thread_id, statement_id, SUBSTRING(sql_text,1,50)
  FROM performance_schema.events_statements_history_long
  WHERE thread_id = @connection_thread
  ORDER BY event_id DESC LIMIT 20;
  1. Bracket-query the stage timings using the statement's event_id / end_event_id:
SET @eid  = (SELECT event_id     FROM performance_schema.events_statements_history_long WHERE statement_id = @statement_id);
SET @eeid = (SELECT end_event_id FROM performance_schema.events_statements_history_long WHERE statement_id = @statement_id);
SELECT event_name, source, (timer_end-timer_start)/1000000000 AS 'milliseconds'
  FROM performance_schema.events_stages_history_long
  WHERE event_id BETWEEN @eid AND @eeid;

Canonical output shape

event_name                              | milliseconds
----------------------------------------+-------------
stage/sql/starting                      |     0.2400
stage/sql/Executing hook on trx begin.  |     0.0010
stage/sql/checking permissions          |     0.0020
stage/sql/Opening tables                |     0.0950
stage/sql/init                          |     0.0050
stage/sql/System lock                   |     0.0110
stage/sql/optimizing                    |     0.0270
stage/sql/statistics                    |     0.1040
stage/sql/preparing                     |     0.0590
stage/sql/executing                     |   735.3020
stage/sql/end                           |     0.0010
stage/sql/query end                     |     0.0020
stage/sql/waiting for handler commit    |     0.0060
stage/sql/closing tables                |     0.0080
stage/sql/freeing items                 |     0.2810
stage/sql/cleaning up                   |     0.0010

The post's worked example: 735.3 ms in stage/sql/executing out of ~736 ms total. This is the common case — most slow OLTP queries are execution-bound. The value of stage profiling is that it would flag System lock / waiting for handler commit / optimizing dominance if those were the bottleneck.

Caveats

  • Overhead — history tracking is not free; fleet-wide enablement has a perf cost PlanetScale names as "small" but real.
  • In-memory — history tables are bounded rings; old statements age out. Run the profile workflow immediately after the query.
  • Thread-ID scoping — PROCESSLIST_ID vs thread_id are different. The post's translation SQL is the canonical form.
  • Timer column arithmetic — (timer_end - timer_start) is in picoseconds; divide by 1e9 for milliseconds, 1e12 for seconds.

Seen in

Last updated · 378 distilled / 1,213 read