Mysql Query Profiler

Query Profiler 会记录当前session中查询语句的资源使用情况，如果会话结束，信息就会丢失，可以使用SHOW PROFILES查看，帮助我们定位性能出在什么地方。
SHOW PROFILES Syntax
SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

type:
    ALL
  | BLOCK IO
  | CONTEXT SWITCHES
  | CPU
  | IPC
  | MEMORY
  | PAGE FAULTS
  | SOURCE
  | SWAPS

type类型的含义：
ALL displays all information
BLOCK IO displays counts for block input and output operations
CONTEXT SWITCHES displays counts for voluntary and involuntary context switches
CPU displays user and system CPU usage times
IPC displays counts for messages sent and received
MEMORY is not currently implemented
PAGE FAULTS displays counts for major and minor page faults
SOURCE displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
SWAPS displays swap counts

mysql> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set (0.00 sec)

--开启profiler
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t;
+------+------+
| a    | b    |
+------+------+
|    1 |    1 |
|    2 |    2 |
+------+------+
2 rows in set (0.00 sec)

mysql> select 1 from dual;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

mysql> show profiles;
+----------+------------+--------------------+
| Query_ID | Duration   | Query              |
+----------+------------+--------------------+
|        1 | 0.00046900 | select * from t    |
|        2 | 0.00019900 | select 1 from dual |
+----------+------------+--------------------+
2 rows in set (0.00 sec)

mysql> show profile cpu,block io for query 1;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000076 | 0.000000 |   0.000000 |         NULL |          NULL |
| checking permissions | 0.000015 | 0.000000 |   0.000000 |         NULL |          NULL |
| Opening tables       | 0.000055 | 0.000000 |   0.000000 |         NULL |          NULL |
| System lock          | 0.000017 | 0.000000 |   0.000000 |         NULL |          NULL |
| init                 | 0.000022 | 0.000000 |   0.000000 |         NULL |          NULL |
| optimizing           | 0.000009 | 0.000000 |   0.000000 |         NULL |          NULL |
| statistics           | 0.000022 | 0.000000 |   0.000000 |         NULL |          NULL |
| preparing            | 0.000014 | 0.000000 |   0.000000 |         NULL |          NULL |
| executing            | 0.000006 | 0.000000 |   0.000000 |         NULL |          NULL |
| Sending data         | 0.000133 | 0.000000 |   0.000000 |         NULL |          NULL |
| end                  | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| query end            | 0.000009 | 0.000000 |   0.000000 |         NULL |          NULL |
| closing tables       | 0.000012 | 0.000000 |   0.000000 |         NULL |          NULL |
| freeing items        | 0.000064 | 0.000000 |   0.000000 |         NULL |          NULL |
| logging slow query   | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| cleaning up          | 0.000005 | 0.000000 |   0.000000 |         NULL |          NULL |
+----------------------+----------+----------+------------+--------------+---------------+
16 rows in set (0.00 sec)

mysql> show profile cpu,block io for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000061 | 0.000000 |   0.000000 |         NULL |          NULL |
| checking permissions | 0.000012 | 0.000000 |   0.000000 |         NULL |          NULL |
| Opening tables       | 0.000015 | 0.000000 |   0.000000 |         NULL |          NULL |
| init                 | 0.000016 | 0.000000 |   0.000000 |         NULL |          NULL |
| optimizing           | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| executing            | 0.000018 | 0.000000 |   0.000000 |         NULL |          NULL |
| end                  | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| query end            | 0.000006 | 0.000000 |   0.000000 |         NULL |          NULL |
| closing tables       | 0.000006 | 0.000000 |   0.000000 |         NULL |          NULL |
| freeing items        | 0.000039 | 0.000000 |   0.000000 |         NULL |          NULL |
| logging slow query   | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| cleaning up          | 0.000005 | 0.000000 |   0.000000 |         NULL |          NULL |
+----------------------+----------+----------+------------+--------------+---------------+
12 rows in set (0.00 sec)

mysql> show profile cpu,block io;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000061 | 0.000000 |   0.000000 |         NULL |          NULL |
| checking permissions | 0.000012 | 0.000000 |   0.000000 |         NULL |          NULL |
| Opening tables       | 0.000015 | 0.000000 |   0.000000 |         NULL |          NULL |
| init                 | 0.000016 | 0.000000 |   0.000000 |         NULL |          NULL |
| optimizing           | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| executing            | 0.000018 | 0.000000 |   0.000000 |         NULL |          NULL |
| end                  | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| query end            | 0.000006 | 0.000000 |   0.000000 |         NULL |          NULL |
| closing tables       | 0.000006 | 0.000000 |   0.000000 |         NULL |          NULL |
| freeing items        | 0.000039 | 0.000000 |   0.000000 |         NULL |          NULL |
| logging slow query   | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| cleaning up          | 0.000005 | 0.000000 |   0.000000 |         NULL |          NULL |
+----------------------+----------+----------+------------+--------------+---------------+
12 rows in set (0.00 sec)

mysql> show profile;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000061 |
| checking permissions | 0.000012 |
| Opening tables       | 0.000015 |
| init                 | 0.000016 |
| optimizing           | 0.000007 |
| executing            | 0.000018 |
| end                  | 0.000008 |
| query end            | 0.000006 |
| closing tables       | 0.000006 |
| freeing items        | 0.000039 |
| logging slow query   | 0.000007 |
| cleaning up          | 0.000005 |
+----------------------+----------+
12 rows in set (0.01 sec)

mysql> show profiles;
+----------+------------+--------------------+
| Query_ID | Duration   | Query              |
+----------+------------+--------------------+
|        1 | 0.00046900 | select * from t    |
|        2 | 0.00019900 | select 1 from dual |
+----------+------------+--------------------+
2 rows in set (0.00 sec)

--关闭profiler
mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)

show profile会显示最新查询的信息
也可以直接查询INFORMATION_SCHEMA.PROFILING，显示查询语句的资源使用情况，以下两种方式是等效的：
SHOW PROFILE FOR QUERY 2;

SELECT STATE, FORMAT(DURATION, 6) AS DURATION
FROM INFORMATION_SCHEMA.PROFILING
WHERE QUERY_ID = 2 ORDER BY SEQ;

INFORMATION_SCHEMA.PROFILING字段含义：
QUERY_ID is a numeric statement identifier.
SEQ is a sequence number indicating the display order for rows with the same QUERY_ID value.
STATE is the profiling state to which the row measurements apply.
DURATION indicates how long statement execution remained in the given state, in seconds.
CPU_USER and CPU_SYSTEM indicate user and system CPU use, in seconds.
CONTEXT_VOLUNTARY and CONTEXT_INVOLUNTARY indicate how many voluntary and involuntary context switches occurred.
BLOCK_OPS_IN and BLOCK_OPS_OUT indicate the number of block input and output operations.
MESSAGES_SENT and MESSAGES_RECEIVED indicate the number of communication messages sent and received.
PAGE_FAULTS_MAJOR and PAGE_FAULTS_MINOR indicate the number of major and minor page faults.
SWAPS indicates how many swaps occurred.
SOURCE_FUNCTION, SOURCE_FILE, and SOURCE_LINE provide information indicating where in the source code the profiled state executes.