轉自：http://www.percona.com/blog/2015/04/16/profiling-mysql-queries-from-performance-schema/?utm_source=tuicool
When optimizing queries and investigating performance issues, MySQL comes with built in support for profiling queries aka SET profiling = 1; . This is already awesome and simple to use, but why the PERFORMANCE_SCHEMA alternative?
Because profiling will be removed soon (already deprecated on MySQL 5.6 ad 5.7); the built-in profiling capability can only be enabled per session. This means that you cannot capture profiling information for queries running from other connections. If you are using Percona Server, the profiling option for log_slow_verbosity is a nice alternative, unfortunately, not everyone is using Percona Server.
Now, for a quick demo: I execute a simple query and profile it below. Note that all of these commands are executed from a single session to my test instance.
mysql> SHOW PROFILES; +----------+------------+----------------------------------------+ | Query_ID | Duration | Query | +----------+------------+----------------------------------------+ | 1 | 0.00011150 | SELECT * FROM sysbench.sbtest1 LIMIT 1 | +----------+------------+----------------------------------------+ 1 row in set, 1 warning (0.00 sec) mysql> SHOW PROFILE SOURCE FOR QUERY 1; +----------------------+----------+-----------------------+------------------+-------------+ | Status | Duration | Source_function | Source_file | Source_line | +----------------------+----------+-----------------------+------------------+-------------+ | starting | 0.000017 | NULL | NULL | NULL | | checking permissions | 0.000003 | check_access | sql_parse.cc | 5797 | | Opening tables | 0.000021 | open_tables | sql_base.cc | 5156 | | init | 0.000009 | mysql_prepare_select | sql_select.cc | 1050 | | System lock | 0.000005 | mysql_lock_tables | lock.cc | 306 | | optimizing | 0.000002 | optimize | sql_optimizer.cc | 138 | | statistics | 0.000006 | optimize | sql_optimizer.cc | 381 | | preparing | 0.000005 | optimize | sql_optimizer.cc | 504 | | executing | 0.000001 | exec | sql_executor.cc | 110 | | Sending data | 0.000025 | exec | sql_executor.cc | 190 | | end | 0.000002 | mysql_execute_select | sql_select.cc | 1105 | | query end | 0.000003 | mysql_execute_command | sql_parse.cc | 5465 | | closing tables | 0.000004 | mysql_execute_command | sql_parse.cc | 5544 | | freeing items | 0.000005 | mysql_parse | sql_parse.cc | 6969 | | cleaning up | 0.000006 | dispatch_command | sql_parse.cc | 1874 | +----------------------+----------+-----------------------+------------------+-------------+ 15 rows in set, 1 warning (0.00 sec)
To demonstrate how we can achieve the same with Performance Schema, we first identify our current connection id. In the real world, you might want to get the connection/processlist id of the thread you want to watch i.e. from SHOW PROCESSLIST .
mysql> SELECT THREAD_ID INTO @my_thread_id
-> FROM threads WHERE PROCESSLIST_ID = CONNECTION_ID();
Query OK, 1 row affected (0.00 sec)
Next, we identify the bounding EVENT_IDs for the statement stages. We will look for the statement we wanted to profile using the query below from the events_statements_history_long table. Your LIMIT clause may vary depending on how much queries the server might be getting.
mysql> SELECT THREAD_ID, EVENT_ID, END_EVENT_ID, SQL_TEXT, NESTING_EVENT_ID
-> FROM events_statements_history_long
-> WHERE THREAD_ID = @my_thread_id
-> AND EVENT_NAME = 'statement/sql/select'
-> ORDER BY EVENT_ID DESC LIMIT 3 G
*************************** 1. row ***************************
THREAD_ID: 13848
EVENT_ID: 419
END_EVENT_ID: 434
SQL_TEXT: SELECT THREAD_ID INTO @my_thread_id
FROM threads WHERE PROCESSLIST_ID = CONNECTION_ID()
NESTING_EVENT_ID: NULL
*************************** 2. row ***************************
THREAD_ID: 13848
EVENT_ID: 374
END_EVENT_ID: 392
SQL_TEXT: SELECT * FROM sysbench.sbtest1 LIMIT 1
NESTING_EVENT_ID: NULL
*************************** 3. row ***************************
THREAD_ID: 13848
EVENT_ID: 353
END_EVENT_ID: 364
SQL_TEXT: select @@version_comment limit 1
NESTING_EVENT_ID: NULL
3 rows in set (0.02 sec)
From the results above, we are mostly interested with the EVENT_ID and END_EVENT_ID values from the second row, this will give us the stage events of this particular query from the events_stages_history_long table.
mysql> SELECT EVENT_NAME, SOURCE, (TIMER_END-TIMER_START)/1000000000 as 'DURATION (ms)'
-> FROM events_stages_history_long
-> WHERE THREAD_ID = @my_thread_id AND EVENT_ID BETWEEN 374 AND 392;
+--------------------------------+----------------------+---------------+
| EVENT_NAME | SOURCE | DURATION (ms) |
+--------------------------------+----------------------+---------------+
| stage/sql/init | mysqld.cc:998 | 0.0214 |
| stage/sql/checking permissions | sql_parse.cc:5797 | 0.0023 |
| stage/sql/Opening tables | sql_base.cc:5156 | 0.0205 |
| stage/sql/init | sql_select.cc:1050 | 0.0089 |
| stage/sql/System lock | lock.cc:306 | 0.0047 |
| stage/sql/optimizing | sql_optimizer.cc:138 | 0.0016 |
| stage/sql/statistics | sql_optimizer.cc:381 | 0.0058 |
| stage/sql/preparing | sql_optimizer.cc:504 | 0.0044 |
| stage/sql/executing | sql_executor.cc:110 | 0.0008 |
| stage/sql/Sending data | sql_executor.cc:190 | 0.0251 |
| stage/sql/end | sql_select.cc:1105 | 0.0017 |
| stage/sql/query end | sql_parse.cc:5465 | 0.0031 |
| stage/sql/closing tables | sql_parse.cc:5544 | 0.0037 |
| stage/sql/freeing items | sql_parse.cc:6969 | 0.0056 |
| stage/sql/cleaning up | sql_parse.cc:1874 | 0.0006 |
+--------------------------------+----------------------+---------------+
15 rows in set (0.01 sec)
As you can see the results are pretty close, not exactly the same but close. SHOW PROFILE shows Duration in seconds, while the results above is in milliseconds.
Some limitations to this method though:
