MySQL的SQL Profiler性能分析器

xuxiaohui9216

　　MySQL从5.0开始提供了 SQL Profiler性能分析器，其主要用途是显示 sql 执行的整个过程中各项资源的使用情况。这个工具可以很好的展示出 SQL 的性能问题。
　　下面我们从五个角度并举例介绍MySQL SQL Profiler的使用方法(尤其第五个角度,从源码出发,分析了重要的几个项目的含义,便于读者准确掌握其含义)：
　　一检查是否启用性能分析功能
　　mysql> select version();
　　+--------------+
　　| version() |
　　+--------------+
　　| 5.6.12 |
　　+--------------+
　　1 row in set (0.00 sec)
　　mysql> SELECT @@profiling;
　　+-------------+
　　| @@profiling |
　　+-------------+
　　| 0 |
　　+-------------+
　　1 row in set, 1 warning (0.00 sec)
　　说明：
　　0表示没有开启性能分析功能
　　二开启性能关系功能
　　mysql> SET profiling = 1;
　　Query OK, 0 rows affected (0.00 sec)
　　三查询获取性能信息
　　3.1）显示单条SQL语句的执行过程的性能信息:
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
　　说明
　　获取执行过的SQL语句对资源的使用情况。
[FOR QUERY n]表示可以指定获取某个特定的SQL的性能信息，此信息的输出和获取全部SQL语句的输出内容不同，对于查看特定的语句的过程环节，更有帮助。　　3.2）显示所有SQL语句的执行情况：
SHOW PROFILE;　　四示例
　　创建表：
　　CREATE TABLE a(col INT);
　　CREATE TABLE b(col INT);
　　执行SQL：
　　mysql> set profiling=1;
　　Query OK, 0 rows affected, 1 warning (0.00 sec)
　　mysql> EXPLAIN SELECT 1 FROM
　　-> a
　　-> LEFT JOIN b ON b.col = a.col
　　-> RIGHT JOIN a AS T0 ON b.col = a.col
　　-> LEFT JOIN a AS T1 ON T1.col = a.col
　　-> RIGHT JOIN b AS T2 ON T2.col = a.col
　　-> JOIN a AS T3 ON T3.col = a.col
　　-> JOIN b AS t4 ON T4.col = a.col;
　　+----+-------------+-------+------+---------------+------+---------+------+------+----------------------------------------------------+

　　|>　　+----+-------------+-------+------+---------------+------+---------+------+------+----------------------------------------------------+
　　| 1 | SIMPLE | a | ALL | NULL | NULL | NULL | NULL | 1 | NULL |
　　| 1 | SIMPLE | b | ALL | NULL | NULL | NULL | NULL | 1 | Using where; Using join buffer (Block Nested Loop) |
　　| 1 | SIMPLE | T0 | ALL | NULL | NULL | NULL | NULL | 1 | Using join buffer (Block Nested Loop) |
　　| 1 | SIMPLE | T1 | ALL | NULL | NULL | NULL | NULL | 1 | Using where; Using join buffer (Block Nested Loop) |
　　| 1 | SIMPLE | T2 | ALL | NULL | NULL | NULL | NULL | 1 | Using where; Using join buffer (Block Nested Loop) |
　　| 1 | SIMPLE | T3 | ALL | NULL | NULL | NULL | NULL | 1 | Using where; Using join buffer (Block Nested Loop) |
　　| 1 | SIMPLE | t4 | ALL | NULL | NULL | NULL | NULL | 1 | Using where; Using join buffer (Block Nested Loop) |
　　+----+-------------+-------+------+---------------+------+---------+------+------+----------------------------------------------------+
　　7 rows in set (0.00 sec)
　　如下输出，有价值的是“Duration”列，标示了一个Query的执行时间
　　mysql> SHOW PROFILES;
　　+----------+------------+-----------------------------------------------------------------------------------------------------------------------------
　　----------------------------------------------------------------------------------------------------+
　　| Query_ID | Duration | Query
　　|
　　+----------+------------+-----------------------------------------------------------------------------------------------------------------------------
　　----------------------------------------------------------------------------------------------------+
　　| 1 | 0.00274225 | EXPLAIN SELECT 1 FROM
　　a
　　LEFT JOIN b ON b.col = a.col
　　RIGHT JOIN a AS T0 ON b.col = a.col
　　LEFT JOIN a AS T1 ON T1.col = a.col
　　RIGHT JOIN b AS T2 ON T2.col = a.col
　　JOIN a AS T3 ON T3.col = a.col
　　JOIN b AS t4 ON T4.col = a.col |
　　+----------+------------+-----------------------------------------------------------------------------------------------------------------------------
　　----------------------------------------------------------------------------------------------------+
　　1 row in set, 1 warning (0.00 sec)
　　如下可以根据上条语句的输出信息中的“Query_ID”列的值，查询一条语句的具体情况
　　
　　mysql> SHOW PROFILE ALL FOR QUERY 1;
　　+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+--
　　-----------------+-------------------+-------------------+-------+-----------------+------------------+-------------+
　　| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | M
　　essages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file      | Source_line |
　　+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+--
　　-----------------+-------------------+-------------------+-------+-----------------+------------------+-------------+
　　| starting             | 0.000543 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL | NULL            | NULL             |        NULL |
　　| checking permissions | 0.000018 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| checking permissions | 0.000010 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| checking permissions | 0.000009 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| checking permissions | 0.000014 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| checking permissions | 0.000016 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| checking permissions | 0.000013 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| checking permissions | 0.000018 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5256 |
　　| Opening tables       | 0.000259 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_base.cc      |        4911 |
　　| init                 | 0.000212 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_select.cc    |        1050 |
　　| System lock          | 0.000082 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | lock.cc          |         304 |
　　| optimizing           | 0.000149 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_optimizer.cc |         138 |
　　| statistics           | 0.000280 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_optimizer.cc |         362 |
　　| preparing            | 0.000121 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_optimizer.cc |         485 |
　　| explaining           | 0.000423 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_select.cc    |         850 |
　　| query end            | 0.000117 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        4956 |
　　| closing tables       | 0.000121 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        5004 |
　　| freeing items        | 0.000280 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        6264 |
　　| cleaning up          | 0.000060 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |
　　NULL |              NULL |              NULL |  NULL |        | sql_parse.cc     |        1774 |
　　+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+--
　　-----------------+-------------------+-------------------+-------+-----------------+------------------+-------------+
　　19 rows in set, 1 warning (0.00 sec)
　　五通过源码分析了解性能分析工具输出信息所表达的含义
　　看这个简单运行结果，可以分析一条SQL语句执行的各个阶段的时间花费(根据源码分析得到的内容分析直接加在右侧)：
　　mysql> SHOW PROFILE FOR QUERY 1;
　　+----------------------+----------+
　　| Status               | Duration |
　　+----------------------+----------+
　　| starting             | 0.000543 |
　　| checking permissions | 0.000018 |
　　| checking permissions | 0.000010 |
　　| checking permissions | 0.000009 |
　　| checking permissions | 0.000014 |
　　| checking permissions | 0.000016 |
　　| checking permissions | 0.000013 |
　　| checking permissions | 0.000018 |
　　| Opening tables       | 0.000259 |
　　| init                 | 0.000212 |
　　| System lock          | 0.000082 |
　　| optimizing           | 0.000149 |在JOIN::optimize()在函数中，大多数逻辑查询优化工作（如外连接消除/条件化简/）在这个阶段完成，如果这个时间花费多，则检查SQL进行逻辑查询优化调优工作
　　| statistics           | 0.000280 |调用make_join_statistics()函数完成多表连接，主要执行的是物理查询优化，如果这个时间多，则多表连接的过程需要优化尤其注意要连接的表的个数较多的话，需要查看optimizer_search_depth的值，如果值很大，则需要修改其值为一个较小的数，如7
　　| preparing            | 0.000121 |多表连接完成，准备其他一些优化操作，为调用JOIN::exec()作执行前的准备工作
　　| explaining           | 0.000423 |
　　| query end            | 0.000117 |
　　| closing tables       | 0.000121 |
　　| freeing items        | 0.000280 |
　　| cleaning up          | 0.000060 |
　　+----------------------+----------+
　　19 rows in set, 1 warning (0.00 sec)
说明：　　第一列，在代码中，通常都是调用如下类似语句完成：
　　thd_proc_info(thd, "preparing");，对应的就是“| preparing | 0.000121 |”这一行的内容。