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!
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
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).
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
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
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
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
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 |
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.
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.
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.