MySQL Query Profiling Using Performance Schema
Imagine having a tool that can automatically detect JPA and Hibernate performance issues. Wouldn’t that be just awesome?
Well, Hypersistence Optimizer is that tool! And it works with Spring Boot, Spring Framework, Jakarta EE, Java EE, Quarkus, or Play Framework.
So, enjoy spending your time on the things you love rather than fixing performance issues in your production system on a Saturday night!
Introduction
In this article, I’m going to explain how to do query profiling using the MySQL Performance Schema.
The Performance Schema has been available since MySQL 5.5.3 and allows MySQL to instrument SQL queries and store their trace information in various tables that you can later inspect in order to determine why a given SQL statement is slow.
On older versions of MySQL, you might have used the SHOW PROFILE command, but since this feature has been deprecated, you should now use the Performance Schema for SQL query profiling.
Enabling the MySQL Performance Schema
The Performance Schema is enabled by default, so unless you explicitly disabled it, the performance_schema variable should have the value of ON:
SHOW VARIABLES LIKE 'performance_schema'; | Variable_name | Value | |--------------------|-------| | performance_schema | ON |
If the Performance Schema was disabled, you could enable it by setting the performance_schema variable to the value of ON in the MySQL configuration file (e.g., my.cfg on Linux or my.ini on Windows).
[mysqld] performance_schema=ON
MySQL Performance Schema Tables
The MySQL Performance Schema has over one hundred tables, which you can see by running the following SQL query against the information_schema:
SELECT table_name FROM information_schema.tables WHERE table_schema = 'performance_schema'; | TABLE_NAME | |------------------------------------------------------| | accounts | | binary_log_transaction_compression_stats | | cond_instances | | data_lock_waits | | data_locks | | error_log | | events_errors_summary_by_account_by_error | | events_errors_summary_by_host_by_error | | events_errors_summary_by_thread_by_error | | events_errors_summary_by_user_by_error | | events_errors_summary_global_by_error | | events_stages_current | | events_stages_history | | events_stages_history_long | | events_stages_summary_by_account_by_event_name | | events_stages_summary_by_host_by_event_name | | events_stages_summary_by_thread_by_event_name | | events_stages_summary_by_user_by_event_name | | events_stages_summary_global_by_event_name | | events_statements_current | | events_statements_histogram_by_digest | | events_statements_histogram_global | | events_statements_history | | events_statements_history_long | | events_statements_summary_by_account_by_event_name | | events_statements_summary_by_digest | | events_statements_summary_by_host_by_event_name | | events_statements_summary_by_program | | events_statements_summary_by_thread_by_event_name | | events_statements_summary_by_user_by_event_name | | events_statements_summary_global_by_event_name | | events_transactions_current | | events_transactions_history | | events_transactions_history_long | | events_transactions_summary_by_account_by_event_name | | events_transactions_summary_by_host_by_event_name | | events_transactions_summary_by_thread_by_event_name | | events_transactions_summary_by_user_by_event_name | | events_transactions_summary_global_by_event_name | | events_waits_current | | events_waits_history | | events_waits_history_long | | events_waits_summary_by_account_by_event_name | | events_waits_summary_by_host_by_event_name | | events_waits_summary_by_instance | | events_waits_summary_by_thread_by_event_name | | events_waits_summary_by_user_by_event_name | | events_waits_summary_global_by_event_name | | file_instances | | file_summary_by_event_name | | file_summary_by_instance | | global_status | | global_variables | | host_cache | | hosts | | keyring_keys | | log_status | | memory_summary_by_account_by_event_name | | memory_summary_by_host_by_event_name | | memory_summary_by_thread_by_event_name | | memory_summary_by_user_by_event_name | | memory_summary_global_by_event_name | | metadata_locks | | mutex_instances | | objects_summary_global_by_type | | performance_timers | | persisted_variables | | prepared_statements_instances | | processlist | | replication_applier_configuration | | replication_applier_filters | | replication_applier_global_filters | | replication_applier_status | | replication_applier_status_by_coordinator | | replication_applier_status_by_worker | | replication_asynchronous_connection_failover | | replication_connection_configuration | | replication_connection_status | | replication_group_member_stats | | replication_group_members | | rwlock_instances | | session_account_connect_attrs | | session_connect_attrs | | session_status | | session_variables | | setup_actors | | setup_consumers | | setup_instruments | | setup_objects | | setup_threads | | socket_instances | | socket_summary_by_event_name | | socket_summary_by_instance | | status_by_account | | status_by_host | | status_by_thread | | status_by_user | | table_handles | | table_io_waits_summary_by_index_usage | | table_io_waits_summary_by_table | | table_lock_waits_summary_by_table | | threads | | tls_channel_status | | user_defined_functions | | user_variables_by_thread | | users | | variables_by_thread | | variables_info |
The MySQL manual provides an explanation for each of those tables.
Enable Query Profiling using the MySQL Performance Schema
The setup_instruments table allows us to control the SQL instrumentation process on a per-stage basis.
For instance, to see what SQL stages are instrumented, you can run the following query:
SELECT
name,
enabled,
timed
FROM performance_schema.setup_instruments
WHERE name RLIKE 'stage/sql/';
| name | enabled | timed |
|----------------------------------------------------------------------------|---------|-------|
| stage/sql/After create | NO | NO |
| stage/sql/preparing for alter table | NO | NO |
| stage/sql/altering table | NO | NO |
| stage/sql/committing alter table to storage engine | NO | NO |
| stage/sql/Changing master | NO | NO |
| stage/sql/Checking master version | NO | NO |
| stage/sql/checking permissions | NO | NO |
| stage/sql/cleaning up | NO | NO |
| stage/sql/closing tables | NO | NO |
| stage/sql/Compressing gtid_executed table | NO | NO |
| stage/sql/Connecting to master | NO | NO |
| stage/sql/converting HEAP to ondisk | NO | NO |
| stage/sql/copy to tmp table | YES | YES |
| stage/sql/creating table | NO | NO |
| stage/sql/Creating tmp table | NO | NO |
| stage/sql/deleting from main table | NO | NO |
| stage/sql/deleting from reference tables | NO | NO |
| stage/sql/discard_or_import_tablespace | NO | NO |
| stage/sql/end | NO | NO |
| stage/sql/executing | NO | NO |
| stage/sql/Execution of init_command | NO | NO |
| stage/sql/explaining | NO | NO |
| stage/sql/Finished reading one binlog; switching to next binlog | NO | NO |
| stage/sql/Flushing relay log and master info repository. | NO | NO |
| stage/sql/Flushing relay-log info file. | NO | NO |
| stage/sql/freeing items | NO | NO |
| stage/sql/FULLTEXT initialization | NO | NO |
| stage/sql/init | NO | NO |
| stage/sql/Killing slave | NO | NO |
| stage/sql/logging slow query | NO | NO |
| stage/sql/Making temporary file (append) before replaying LOAD DATA INFILE | NO | NO |
| stage/sql/manage keys | NO | NO |
| stage/sql/Master has sent all binlog to slave; waiting for more updates | NO | NO |
| stage/sql/Opening tables | NO | NO |
| stage/sql/optimizing | NO | NO |
| stage/sql/preparing | NO | NO |
| stage/sql/Purging old relay logs | NO | NO |
| stage/sql/query end | NO | NO |
| stage/sql/Queueing master event to the relay log | NO | NO |
| stage/sql/Reading event from the relay log | NO | NO |
| stage/sql/Registering slave on master | NO | NO |
| stage/sql/removing tmp table | NO | NO |
| stage/sql/rename | NO | NO |
| stage/sql/rename result table | NO | NO |
| stage/sql/Requesting binlog dump | NO | NO |
| stage/sql/Searching rows for update | NO | NO |
| stage/sql/Sending binlog event to slave | NO | NO |
| stage/sql/setup | NO | NO |
| stage/sql/Slave has read all relay log; waiting for more updates | NO | NO |
| stage/sql/Waiting for an event from Coordinator | NO | NO |
| stage/sql/Waiting for slave workers to process their queues | NO | NO |
| stage/sql/Waiting for Slave Worker queue | NO | NO |
| stage/sql/Waiting for Slave Workers to free pending events | NO | NO |
| stage/sql/Waiting for Slave Worker to release partition | NO | NO |
| stage/sql/Waiting for workers to exit | NO | NO |
| stage/sql/Applying batch of row changes (write) | YES | YES |
| stage/sql/Applying batch of row changes (update) | YES | YES |
| stage/sql/Applying batch of row changes (delete) | YES | YES |
| stage/sql/Waiting until MASTER_DELAY seconds after master executed event | NO | NO |
| stage/sql/statistics | NO | NO |
| stage/sql/System lock | NO | NO |
| stage/sql/update | NO | NO |
| stage/sql/updating | NO | NO |
| stage/sql/updating main table | NO | NO |
| stage/sql/updating reference tables | NO | NO |
| stage/sql/User sleep | NO | NO |
| stage/sql/verifying table | NO | NO |
| stage/sql/Waiting for GTID to be committed | NO | NO |
| stage/sql/waiting for handler commit | NO | NO |
| stage/sql/Waiting for master to send event | NO | NO |
| stage/sql/Waiting for master update | NO | NO |
| stage/sql/Waiting for the slave SQL thread to free enough relay log space | NO | NO |
| stage/sql/Waiting for slave mutex on exit | NO | NO |
| stage/sql/Waiting for slave thread to start | NO | NO |
| stage/sql/Waiting for table flush | NO | NO |
| stage/sql/Waiting for the next event in relay log | NO | NO |
| stage/sql/Waiting for the slave SQL thread to advance position | NO | NO |
| stage/sql/Waiting to finalize termination | NO | NO |
| stage/sql/Waiting for preceding transaction to commit | NO | NO |
| stage/sql/Waiting for dependent transaction to commit | NO | NO |
| stage/sql/Suspending | NO | NO |
| stage/sql/starting | NO | NO |
| stage/sql/Waiting for no channel reference. | NO | NO |
| stage/sql/Executing hook on transaction begin. | NO | NO |
| stage/sql/Waiting for disk space | NO | NO |
| stage/sql/Compressing transaction changes. | NO | NO |
| stage/sql/Decompressing transaction changes. | NO | NO |
| stage/sql/Waiting on empty queue | NO | NO |
| stage/sql/Waiting for next activation | NO | NO |
| stage/sql/Waiting for the scheduler to stop | NO | NO |
| stage/sql/Waiting for global read lock | NO | NO |
| stage/sql/Waiting for backup lock | NO | NO |
| stage/sql/Waiting for tablespace metadata lock | NO | NO |
| stage/sql/Waiting for schema metadata lock | NO | NO |
| stage/sql/Waiting for table metadata lock | NO | NO |
| stage/sql/Waiting for stored function metadata lock | NO | NO |
| stage/sql/Waiting for stored procedure metadata lock | NO | NO |
| stage/sql/Waiting for trigger metadata lock | NO | NO |
| stage/sql/Waiting for event metadata lock | NO | NO |
| stage/sql/Waiting for commit lock | NO | NO |
| stage/sql/User lock | NO | NO |
| stage/sql/Waiting for locking service lock | NO | NO |
| stage/sql/Waiting for spatial reference system lock | NO | NO |
| stage/sql/Waiting for acl cache lock | NO | NO |
| stage/sql/Waiting for column statistics lock | NO | NO |
| stage/sql/Waiting for resource groups metadata lock | NO | NO |
| stage/sql/Waiting for foreign key metadata lock | NO | NO |
| stage/sql/Waiting for check constraint metadata lock | NO | NO |
As you can see, there are lots of stages that are not instrumented by default, so let’s enable all of them using the following statement:
UPDATE performance_schema.setup_instruments SET enabled = 'YES', timed = 'YES'
By default, MySQL does not populate all of those Performance Schema tables. To find out which of them are disabled and enable the ones you are interested in monitoring, you need to check the setup_consumers using the following SQL query:
SELECT * FROM performance_schema.setup_consumers | NAME | ENABLED | |----------------------------------|---------| | events_stages_current | NO | | events_stages_history | NO | | events_stages_history_long | NO | | events_statements_current | YES | | events_statements_history | YES | | events_statements_history_long | NO | | events_transactions_current | YES | | events_transactions_history | YES | | events_transactions_history_long | NO | | events_waits_current | NO |
If you want to activate monitoring for all these tables, then you need to set the enabled column to the value of YES:
UPDATE performance_schema.setup_consumers SET enabled = 'YES'
Doing query profiling using the MySQL Performance Schema
Let’s assume we are running a non-trivial SQL query, like the following one:
SELECT id, parent_id, review, created_on, score, total_score
FROM (
SELECT
id, parent_id, review, created_on, score, total_score,
DENSE_RANK() OVER (ORDER BY total_score DESC) AS ranking
FROM (
SELECT
id, parent_id, review, created_on, score,
SUM(score) OVER (PARTITION BY root_id) AS total_score
FROM (
WITH RECURSIVE post_comment_score(
id, root_id, post_id, parent_id, review, created_on, score)
AS (
SELECT
id, id, post_id, parent_id, review, created_on, score
FROM post_comment
WHERE post_id = 1 AND parent_id IS NULL
UNION ALL
SELECT pc.id, pcs.root_id, pc.post_id, pc.parent_id,
pc.review, pc.created_on, pc.score
FROM post_comment pc
INNER JOIN post_comment_score pcs ON pc.parent_id = pcs.id
)
SELECT id, parent_id, root_id, review, created_on, score
FROM post_comment_score
) total_score_comment
) total_score_ranking
) total_score_filtering
WHERE ranking <= 3
ORDER BY total_score DESC, id ASC
To see how this query performance, we can inspect the events_statements_history_long table:
SELECT
event_id AS "Event Id",
TRUNCATE(timer_wait / 10000000000, 3) AS "Query Time Millis",
TRUNCATE(lock_time / 10000000000, 3) AS "Lock Time Millis",
rows_sent AS "Result Set Size",
rows_examined AS "Scanned Row Count",
created_tmp_tables AS "Temp Table Count",
select_scan AS "Table Scan Count",
sort_scan AS "Table Sort Count",
sort_rows AS "Sorted Row Count"
FROM
performance_schema.events_statements_history_long
WHERE
sql_text LIKE '% dense_rank() OVER (ORDER BY total_score DESC) %'
AND digest = '46db1c8ad43a3824ccfe57fd55c899ab0c1734b600b2e119a35cebc7f2ddf613'
| Event Id | Query Time Millis | Lock Time Millis | Result Set Size | Scanned Row Count | Temp Table Count | Table Scan Count | Table Sort Count | Sorted Row Count |
|----------|-------------------|------------------|-----------------|-------------------|------------------|------------------|------------------|------------------|
| 261 | 0.165 | 0.096 | 10 | 22 | 4 | 4 | 3 | 34 |
The 46db1c8ad43a3824ccfe57fd55c899ab0c1734b600b2e119a35cebc7f2ddf613 is the hash of the SQL query we are interested in inspecting, and I got the value by inspecting the query result set without providing the digest filtering option.
The Event_Id of this SQL query is 261, which we can use to verify the SQL stages that were executed by MySQL when running this query. Therefore, we need to inspect the events_stages_history_long table and filter the nesting_event_id column by the event id of the previous SQL query (e.g., 261 in our case).
SELECT
event_name AS "Stage Name",
TRUNCATE(timer_wait / 10000000000, 3) AS "Stage Time Millis"
FROM performance_schema.events_stages_history_long
WHERE nesting_event_id = 261
ORDER BY timer_start
| Stage Name | Stage Time Millis |
|------------------------------------------------|-------------------|
| stage/sql/starting | 0.020 |
| stage/sql/Executing hook on transaction begin. | 0.000 |
| stage/sql/starting | 0.000 |
| stage/sql/checking permissions | 0.000 |
| stage/sql/Opening tables | 0.076 |
| stage/sql/init | 0.000 |
| stage/sql/System lock | 0.000 |
| stage/sql/optimizing | 0.000 |
| stage/sql/statistics | 0.009 |
| stage/sql/preparing | 0.001 |
| stage/sql/optimizing | 0.000 |
| stage/sql/statistics | 0.001 |
| stage/sql/preparing | 0.001 |
| stage/sql/statistics | 0.000 |
| stage/sql/preparing | 0.004 |
| stage/sql/Creating tmp table | 0.004 |
| stage/sql/statistics | 0.000 |
| stage/sql/preparing | 0.000 |
| stage/sql/Creating tmp table | 0.003 |
| stage/sql/statistics | 0.000 |
| stage/sql/preparing | 0.002 |
| stage/sql/executing | 0.024 |
| stage/sql/end | 0.000 |
| stage/sql/query end | 0.000 |
| stage/sql/waiting for handler commit | 0.001 |
| stage/sql/removing tmp table | 0.000 |
| stage/sql/removing tmp table | 0.000 |
| stage/sql/removing tmp table | 0.000 |
| stage/sql/removing tmp table | 0.000 |
| stage/sql/closing tables | 0.000 |
| stage/sql/freeing items | 0.007 |
| stage/sql/cleaning up | 0.000 |
For this particular query, the stage/sql/Opening tables and stage/sql/executing stages take more than other stages, although they are also very fast.
I'm running an online workshop on the 20-21 and 23-24 of November about High-Performance Java Persistence.
If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.
Conclusion
Query profiling is a very useful feature when you are trying to find out what happens during a certain SQL query execution. While the SQL execution plan can provide you info about the logical operations used during query execution, the query profile lists the physical operations instead.
