Profiling QueriesΒΆ
EXPLAIN only shows a pre-execution perspective of the query’s cost. It does not provide any statistics about the query execution, which can show a more complete picture. As an example, when the optimizer cannot eliminate rows from an index (and adds an attached_condition to a table in EXPLAIN), it doesn’t know how many rows will be eliminated. This can have a trickle-down effect in join conditions as there may be very many or very few lookups to subsequent tables.
MySQL Supports rudimentary profiling of the time spent in each stage of execution via performance_schema, which replaces the earlier SHOW PROFILES command that has since been deprecated in MySQL. For example purposes, I am using a SHOW PROFILES replacement based on the SYS schema, which can be installed as follows:
# via shell
wget http://www.tocker.ca/files/ps-show-profiles.sql
mysql -u root -p < ps-show-profiles.sql
Example 34: Profiling a query with Performance Schema:
# via MySQL
CALL sys.enable_profiling();
CALL sys.show_profiles;
*************************** 1. row ***************************
Event_ID: 22
Duration: 495.02 us
Query: SELECT * FROM Country WHERE co ... Asia' and population > 5000000
1 row in set (0.00 sec)
CALL sys.show_profile_for_event_id(22);
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| starting | 64.82 us |
| checking permissions | 4.10 us |
| Opening tables | 11.87 us |
| init | 29.74 us |
| System lock | 5.63 us |
| optimizing | 8.74 us |
| statistics | 139.38 us |
| preparing | 11.94 us |
| executing | 348.00 ns |
| Sending data | 192.59 us |
| end | 1.17 us |
| query end | 4.60 us |
| closing tables | 4.07 us |
| freeing items | 13.60 us |
| cleaning up | 734.00 ns |
+----------------------+-----------+
15 rows in set (0.00 sec)
It is possible to use the SLEEP() function to demonstrate considerable time spent in a specific stage of execution.
In this query, MySQL will sleep for 5 seconds for every row that matches continent='Antarctica':
SELECT * FROM Country WHERE Continent='Antarctica' and SLEEP(5);
CALL sys.show_profiles();
CALL sys.show_profile_for_event_id(<event_id>);
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| starting | 103.89 us |
| checking permissions | 4.48 us |
| Opening tables | 17.78 us |
| init | 45.75 us |
| System lock | 8.37 us |
| optimizing | 11.98 us |
| statistics | 144.78 us |
| preparing | 15.78 us |
| executing | 634.00 ns |
| Sending data | 116.15 us |
| User sleep | 5.00 s |
| User sleep | 5.00 s |
| User sleep | 5.00 s |
| User sleep | 5.00 s |
| User sleep | 5.00 s |
| end | 2.05 us |
| query end | 5.63 us |
| closing tables | 7.30 us |
| freeing items | 20.19 us |
| cleaning up | 1.20 us |
+----------------------+-----------+
20 rows in set (0.01 sec)
You may find that the profiling output is not always as fine grained in stages as it could be. For example, the Status Sending Data simply means transferring rows between the storage engine and the server. Importantly, the execution time of
temporary tables and sorting is broken down:
SELECT region, count(*) as c FROM Country GROUP BY region;
CALL sys.show_profiles();
CALL sys.show_profile_for_event_id(<event_id>);
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| starting | 87.43 us |
| checking permissions | 4.93 us |
| Opening tables | 17.35 us |
| init | 25.81 us |
| System lock | 9.04 us |
| optimizing | 3.37 us |
| statistics | 18.31 us |
| preparing | 10.94 us |
| Creating tmp table | 35.57 us |
| Sorting result | 2.38 us |
| executing | 741.00 ns |
| Sending data | 446.03 us |
| Creating sort index | 49.45 us |
| end | 1.71 us |
| query end | 4.85 us |
| removing tmp table | 4.71 us |
| closing tables | 6.12 us |
| freeing items | 17.17 us |
| cleaning up | 1.00 us |
+----------------------+-----------+
19 rows in set (0.01 sec)
In addition to profiling information exposed by these helper procedures, performance_schema also
has additional statistics on the actual number of rows that needed sorting, as well as rows sent. This execution-level
analysis complements the pre-execution analysis seen in EXPLAIN:
SELECT * FROM performance_schema.events_statements_history_long
WHERE event_id=<event_id>\G
*************************** 1. row ***************************
THREAD_ID: 3062
EVENT_ID: 1566
END_EVENT_ID: 1585
EVENT_NAME: statement/sql/select
SOURCE: init_net_server_extension.cc:80
TIMER_START: 588883869566277000
TIMER_END: 588883870317683000
TIMER_WAIT: 751406000
LOCK_TIME: 132000000
SQL_TEXT: SELECT region, count(*) as c FROM Country GROUP BY region
DIGEST: d3a04b346fe48da4f1f5c2e06628a245
DIGEST_TEXT: SELECT `region` , COUNT ( * ) AS `c` FROM `Country` GROUP BY `region`
CURRENT_SCHEMA: world
OBJECT_TYPE: NULL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
RETURNED_SQLSTATE: NULL
MESSAGE_TEXT: NULL
ERRORS: 0
WARNINGS: 0
ROWS_AFFECTED: 0
ROWS_SENT: 25
ROWS_EXAMINED: 289
CREATED_TMP_DISK_TABLES: 0
CREATED_TMP_TABLES: 1
SELECT_FULL_JOIN: 0
SELECT_FULL_RANGE_JOIN: 0
SELECT_RANGE: 0
SELECT_RANGE_CHECK: 0
SELECT_SCAN: 1
SORT_MERGE_PASSES: 0
SORT_RANGE: 0
SORT_ROWS: 25
SORT_SCAN: 1
NO_INDEX_USED: 1
NO_GOOD_INDEX_USED: 0
NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
NESTING_EVENT_LEVEL: 0