profile MySQL性能分析工具

分析SQL执行带来的开销是优化SQL的重要手段。在MySQL数据库中,可以通过配置profiling参数来启用SQL剖析。该参数可以在全局和session级别来设置。对于全局级别则作用于整个MySQL实例,而session级别紧影响当前session。该参数开启后,后续执行的SQL语句都将记录其资源开销,诸如IO,上下文切换,CPU,Memory等等。根据这些开销进一步分析当前SQL瓶颈从而进行优化与调整。本文描述了如何使用MySQL profile,不涉及具体的样例分析。

1、有关profile的描述

--当前版本  
root@localhost[sakila]> show variables like 'version';  
 +---------------+---------------------------------------+  
 | Variable_name | Value                                 |  
 +---------------+---------------------------------------+  
 | version       | 5.6.17-enterprise-commercial-advanced |  
 +---------------+---------------------------------------+  
   
--查看profiling系统变量  
root@localhost[sakila]> show variables like '%profil%';  
 +------------------------+-------+  
 | Variable_name          | Value |  
 +------------------------+-------+  
 | have_profiling         | YES   |   --只读变量,用于控制是否由系统变量开启或禁用profiling  
 | profiling              | OFF   |   --开启SQL语句剖析功能  
 | profiling_history_size | 15    |   --设置保留profiling的数目,缺省为15,范围为0至100,为0时将禁用profiling  
 +------------------------+-------+  
   
--获取profile的帮助  
root@localhost[sakila]> help profile;  
 Name: 'SHOW PROFILE'  
 Description:  
 Syntax:  
 SHOW PROFILE [type [, type] ... ]  
     [FOR QUERY n]  
     [LIMIT row_count [OFFSET offset]]  
   
 type:  
     ALL                --显示所有的开销信息  
   | BLOCK IO           --显示块IO相关开销  
   | CONTEXT SWITCHES   --上下文切换相关开销  
   | CPU                --显示CPU相关开销信息  
   | IPC                --显示发送和接收相关开销信息  
   | MEMORY             --显示内存相关开销信息  
   | PAGE FAULTS        --显示页面错误相关开销信息  
   | SOURCE             --显示和Source_function,Source_file,Source_line相关的开销信息  
   | SWAPS              --显示交换次数相关开销的信息   
   

--上面描述从5.6.7开始该命令将会被移除,用Performance Schema instead代替  
--在Oracle数据库中,是通过autotrace来剖析单条SQL并获取真实的执行计划以及其开销信息 

2、开启porfiling

--启用session级别的profiling  
 root@localhost[sakila]> set profiling=1;  
 Query OK, 0 rows affected, 1 warning (0.00 sec)  
   
--验证修改后的结果  
root@localhost[sakila]> show variables like '%profil%';  
 +------------------------+-------+  
 | Variable_name          | Value |  
 +------------------------+-------+  
 | have_profiling         | YES   |  
 | profiling              | ON    |  
 | profiling_history_size | 15    |  
 +------------------------+-------+  
   
--发布SQL查询  
root@localhost[sakila]> select count(*) from customer;  
 +----------+  
 | count(*) |  
 +----------+  
 |      599 |  
 +----------+  
   
--查看当前session所有已产生的profile  
 root@localhost[sakila]> show profiles;  
 +----------+------------+--------------------------------+  
 | Query_ID | Duration   | Query                          |  
 +----------+------------+--------------------------------+  
 |        1 | 0.00253600 | show variables like '%profil%' |  
 |        2 | 0.00138150 | select count(*) from customer  |  
 +----------+------------+--------------------------------+  
 2 rows in set, 1 warning (0.01 sec)  
   
--我们看到有2个warning,之前一个,现在一个  
root@localhost[sakila]> show warnings;    --下面的结果表明SHOW PROFILES将来会被Performance Schema替换掉  
 +---------+------+--------------------------------------------------------------------------------------------------------------+  
 | Level   | Code | Message                                                                                                      |  
 +---------+------+--------------------------------------------------------------------------------------------------------------+  
 | Warning | 1287 | 'SHOW PROFILES' is deprecated and will be removed in a future release. Please use Performance Schema instead |  
 +---------+------+--------------------------------------------------------------------------------------------------------------+  

3、获取SQL语句的开销信息

--可以直接使用show profile来查看上一条SQL语句的开销信息  
--注,show profile之类的语句不会被profiling,即自身不会产生Profiling  
--我们下面的这个show profile查看的是show warnings产生的相应开销  
root@localhost[sakila]> show profile;    
 +----------------+----------+  
 | Status         | Duration |  
 +----------------+----------+  
 | starting       | 0.000141 |  
 | query end      | 0.000058 |  
 | closing tables | 0.000014 |  
 | freeing items  | 0.001802 |  
 | cleaning up    | 0.000272 |  
 +----------------+----------+  
   
--如下面的查询show warnings被添加到profiles  
 root@localhost[sakila]> show profiles;  
 +----------+------------+--------------------------------+  
 | Query_ID | Duration   | Query                          |  
 +----------+------------+--------------------------------+  
 |        1 | 0.00253600 | show variables like '%profil%' |  
 |        2 | 0.00138150 | select count(*) from customer  |  
 |        3 | 0.00228600 | show warnings                  |  
 +----------+------------+--------------------------------+  
   
--获取指定查询的开销  
root@localhost[sakila]> show profile for query 2;  
 +----------------------+----------+  
 | Status               | Duration |  
 +----------------------+----------+  
 | starting             | 0.000148 |  
 | checking permissions | 0.000014 |  
 | Opening tables       | 0.000047 |  
 | init                 | 0.000023 |  
 | System lock          | 0.000035 |  
 | optimizing           | 0.000012 |  
 | statistics           | 0.000019 |  
 | preparing            | 0.000014 |  
 | executing            | 0.000006 |  
 | Sending data         | 0.000990 |  
 | end                  | 0.000010 |  
 | query end            | 0.000011 |  
 | closing tables       | 0.000010 |  
 | freeing items        | 0.000016 |  
 | cleaning up          | 0.000029 |  
 +----------------------+----------+  
   
--查看特定部分的开销,如下为CPU部分的开销  
root@localhost[sakila]> show profile cpu for query 2 ;  
 +----------------------+----------+----------+------------+  
 | Status               | Duration | CPU_user | CPU_system |  
 +----------------------+----------+----------+------------+  
 | starting             | 0.000148 | 0.000000 |   0.000000 |  
 | checking permissions | 0.000014 | 0.000000 |   0.000000 |  
 | Opening tables       | 0.000047 | 0.000000 |   0.000000 |  
 | init                 | 0.000023 | 0.000000 |   0.000000 |  
 | System lock          | 0.000035 | 0.000000 |   0.000000 |  
 | optimizing           | 0.000012 | 0.000000 |   0.000000 |  
 | statistics           | 0.000019 | 0.000000 |   0.000000 |  
 | preparing            | 0.000014 | 0.000000 |   0.000000 |  
 | executing            | 0.000006 | 0.000000 |   0.000000 |  
 | Sending data         | 0.000990 | 0.001000 |   0.000000 |  
 | end                  | 0.000010 | 0.000000 |   0.000000 |  
 | query end            | 0.000011 | 0.000000 |   0.000000 |  
 | closing tables       | 0.000010 | 0.000000 |   0.000000 |  
 | freeing items        | 0.000016 | 0.000000 |   0.000000 |  
 | cleaning up          | 0.000029 | 0.000000 |   0.000000 |  
 +----------------------+----------+----------+------------+  
   
--如下为MEMORY部分的开销  
root@localhost[sakila]> show profile memory for query 2 ;  
 +----------------------+----------+  
 | Status               | Duration |  
 +----------------------+----------+  
 | starting             | 0.000148 |  
 | checking permissions | 0.000014 |  
 | Opening tables       | 0.000047 |  
 | init                 | 0.000023 |  
 | System lock          | 0.000035 |  
 | optimizing           | 0.000012 |  
 | statistics           | 0.000019 |  
 | preparing            | 0.000014 |  
 | executing            | 0.000006 |  
 | Sending data         | 0.000990 |  
 | end                  | 0.000010 |  
 | query end            | 0.000011 |  
 | closing tables       | 0.000010 |  
 | freeing items        | 0.000016 |  
 | cleaning up          | 0.000029 |  
 +----------------------+----------+  
   
--同时查看不同资源开销  
root@localhost[sakila]> show profile block io,cpu for query 2;  
 +----------------------+----------+----------+------------+--------------+---------------+  
 | Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |  
 +----------------------+----------+----------+------------+--------------+---------------+  
 | starting             | 0.000148 | 0.000000 |   0.000000 |            0 |             0 |  
 | checking permissions | 0.000014 | 0.000000 |   0.000000 |            0 |             0 |  
 | Opening tables       | 0.000047 | 0.000000 |   0.000000 |            0 |             0 |  
 | init                 | 0.000023 | 0.000000 |   0.000000 |            0 |             0 |  
 | System lock          | 0.000035 | 0.000000 |   0.000000 |            0 |             0 |  
 | optimizing           | 0.000012 | 0.000000 |   0.000000 |            0 |             0 |  
 | statistics           | 0.000019 | 0.000000 |   0.000000 |            0 |             0 |  
 | preparing            | 0.000014 | 0.000000 |   0.000000 |            0 |             0 |  
 | executing            | 0.000006 | 0.000000 |   0.000000 |            0 |             0 |  
 | Sending data         | 0.000990 | 0.001000 |   0.000000 |            0 |             0 |  
 | end                  | 0.000010 | 0.000000 |   0.000000 |            0 |             0 |  
 | query end            | 0.000011 | 0.000000 |   0.000000 |            0 |             0 |  
 | closing tables       | 0.000010 | 0.000000 |   0.000000 |            0 |             0 |  
 | freeing items        | 0.000016 | 0.000000 |   0.000000 |            0 |             0 |  
 | cleaning up          | 0.000029 | 0.000000 |   0.000000 |            0 |             0 |  
 +----------------------+----------+----------+------------+--------------+---------------+  
   
   
--下面的SQL语句用于查询query_id为2的SQL开销,且按最大耗用时间倒序排列  
root@localhost[sakila]> set @query_id=2;  
   
 root@localhost[sakila]> SELECT STATE, SUM(DURATION) AS Total_R,  
     ->   ROUND(  
     ->        100 * SUM(DURATION) /  
     ->           (SELECT SUM(DURATION)  
     ->            FROM INFORMATION_SCHEMA.PROFILING  
     ->            WHERE QUERY_ID = @query_id  
     ->        ), 2) AS Pct_R,  
     ->     COUNT(*) AS Calls,  
     ->     SUM(DURATION) / COUNT(*) AS "R/Call"  
     ->  FROM INFORMATION_SCHEMA.PROFILING  
     ->  WHERE QUERY_ID = @query_id  
     ->  GROUP BY STATE  
     ->  ORDER BY Total_R DESC;  
 +----------------------+----------+-------+-------+--------------+  
 | STATE                | Total_R  | Pct_R | Calls | R/Call       |  
 +----------------------+----------+-------+-------+--------------+  
 | Sending data         | 0.000990 | 71.53 |     1 | 0.0009900000 |--最大耗用时间部分为发送数据  
 | starting             | 0.000148 | 10.69 |     1 | 0.0001480000 |  
 | Opening tables       | 0.000047 |  3.40 |     1 | 0.0000470000 |  
 | System lock          | 0.000035 |  2.53 |     1 | 0.0000350000 |  
 | cleaning up          | 0.000029 |  2.10 |     1 | 0.0000290000 |  
 | init                 | 0.000023 |  1.66 |     1 | 0.0000230000 |  
 | statistics           | 0.000019 |  1.37 |     1 | 0.0000190000 |  
 | freeing items        | 0.000016 |  1.16 |     1 | 0.0000160000 |  
 | preparing            | 0.000014 |  1.01 |     1 | 0.0000140000 |  
 | checking permissions | 0.000014 |  1.01 |     1 | 0.0000140000 |  
 | optimizing           | 0.000012 |  0.87 |     1 | 0.0000120000 |  
 | query end            | 0.000011 |  0.79 |     1 | 0.0000110000 |  
 | end                  | 0.000010 |  0.72 |     1 | 0.0000100000 |  
 | closing tables       | 0.000010 |  0.72 |     1 | 0.0000100000 |  
 | executing            | 0.000006 |  0.43 |     1 | 0.0000060000 |  
 +----------------------+----------+-------+-------+--------------+  
   
--开启profiling后,我们可以通过show profile等方式查看,其实质是这些开销信息被记录到information_schema.profiling表  
--如下面的查询,部分信息省略  
profiling  
 root@localhost[information_schema]> select * from profiling limit 3,3\G;  
 *************************** 1. row ***************************  
            QUERY_ID: 1  
                 SEQ: 5  
               STATE: init  
            DURATION: 0.000020  
            CPU_USER: 0.000000  
          CPU_SYSTEM: 0.000000  
   CONTEXT_VOLUNTARY: 0  
 CONTEXT_INVOLUNTARY: 0  
        BLOCK_OPS_IN: 0  
       BLOCK_OPS_OUT: 0  
       MESSAGES_SENT: 0  
   MESSAGES_RECEIVED: 0  
   PAGE_FAULTS_MAJOR: 0  
   PAGE_FAULTS_MINOR: 0  
               SWAPS: 0  
     SOURCE_FUNCTION: mysql_prepare_select  
         SOURCE_FILE: sql_select.cc  
         SOURCE_LINE: 1050  
   
--停止profile,可以设置profiling参数,或者在session退出之后,profiling会被自动关闭  
root@localhost[sakila]> set profiling=off;  
 Query OK, 0 rows affected, 1 warning (0.00 sec)    

 

这里还需要注意一点就是,需要安装profile模块才能实现。

1、不过版本要在5.0.37之后。(SHOW PROFILES and SHOW PROFILE were added in MySQL 5.0.37.)

SELECT @@profiling;

来查看是否已经启用profile,如果profilng值为0,可以通过

SET profiling = 1;

来启用。启用profiling之后,我们执行一条查询语句,比如:

select count(*) from roi_summary;

然后show profiles查看如下:

+----------------+------------+----------------------------------+
| Query_ID       | Duration   | Query                            |
+----------------+------------+----------------------------------+
|        1       | 0.00021500 | select @@profiling               |
|        2       | 0.05522700 | select count(*) from roi_summary |
+----------------+------------+----------------------------------+

2 rows in set (0.00 sec)

其中ID为5的语句是刚执行的查询语句


2、变量profiling是用户变量,每次都得重新启用。
以下是我做的一些实验。数据很明显,就不多解释了。

复制代码
mysql> use test
Database changed
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show tables;
+----------------+
| Tables_in_test |
+----------------+
| bag_item | 
| bag_user | 
| score | 
| t | 
+----------------+
4 rows in set (0.03 sec)

mysql> select count(*) from t;
+----------+
| count(*) |
+----------+
| 2097152 | 
+----------+
1 row in set (0.74 sec)

mysql> show profiles;
+----------+------------+------------------------+
| Query_ID | Duration   | Query                  |
+----------+------------+------------------------+
|        1 | 0.02717000 | show tables            | 
|        2 | 0.74770100 | select count(*) from t | 
+----------+------------+------------------------+
2 rows in set (0.00 sec)

mysql> show profile for query 2;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| (initialization)               | 0.000004 | 
| checking query cache for query | 0.000044 | 
| Opening tables                 | 0.000012 | 
| System lock                    | 0.000017 | 
| Table lock                     | 0.00003  | 
| init                           | 0.000013 | 
| optimizing                     | 0.000008 | 
| statistics                     | 0.000013 | 
| preparing                      | 0.000011 | 
| executing                      | 0.000006 | 
| Sending data                   | 0.747313 | 
| end                            | 0.000014 | 
| query end                      | 0.000006 | 
| storing result in query cache  | 0.000006 | 
| freeing items                  | 0.000012 | 
| closing tables                 | 0.000009 | 
| logging slow query             | 0.000183 | 
+--------------------------------+----------+
17 rows in set (0.00 sec)

mysql> show profile block io,cpu for query 2;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| (initialization)               | 0.000004 | 0        | 0          |            0 |             0 | 
| checking query cache for query | 0.000044 | 0        | 0          |            0 |             0 | 
| Opening tables                 | 0.000012 | 0        | 0          |            0 |             0 | 
| System lock                    | 0.000017 | 0        | 0          |            0 |             0 | 
| Table lock                     | 0.00003  | 0        | 0          |            0 |             0 | 
| init                           | 0.000013 | 0        | 0          |            0 |             0 | 
| optimizing                     | 0.000008 | 0        | 0          |            0 |             0 | 
| statistics                     | 0.000013 | 0        | 0          |            0 |             0 | 
| preparing                      | 0.000011 | 0        | 0          |            0 |             0 | 
| executing                      | 0.000006 | 0        | 0          |            0 |             0 | 
| Sending data                   | 0.747313 | 0.746887 | 0          |            0 |             0 | 
| end                            | 0.000014 | 0        | 0          |            0 |             0 | 
| query end                      | 0.000006 | 0        | 0          |            0 |             0 | 
| storing result in query cache  | 0.000006 | 0        | 0          |            0 |             0 | 
| freeing items                  | 0.000012 | 0        | 0          |            0 |             0 | 
| closing tables                 | 0.000009 | 0        | 0          |            0 |             0 | 
| logging slow query             | 0.000183 | 0        | 0          |            0 |             0 | 
+--------------------------------+----------+----------+------------+--------------+---------------+
17 rows in set (0.00 sec)

mysql> insert into t(username) select username from t;
Query OK, 2097152 rows affected (34.17 sec)
Records: 2097152  Duplicates: 0  Warnings: 0

mysql> show profiles;
+----------+-------------+------------------------------------------------+
| Query_ID | Duration    | Query                                          |
+----------+-------------+------------------------------------------------+
|        1 |  0.02717000 | show tables                                    | 
|        2 |  0.74770100 | select count(*) from t                         | 
|        3 |  0.00004200 | show prifile for query 2                       | 
|        4 | 34.30410100 | insert into t(username) select username from t | 
+----------+-------------+------------------------------------------------+
4 rows in set (0.00 sec)

mysql> show profile cpu,block io,memory,swaps for query 4;

mysql> select count(*) from t;
+----------+
| count(*) |
+----------+
|  4194304 | 
+----------+
1 row in set (1.51 sec)

mysql> show profiles;
+----------+-------------+------------------------------------------------+
| Query_ID | Duration    | Query                                          |
+----------+-------------+------------------------------------------------+
|        1 |  0.02717000 | show tables                                    | 
|        2 |  0.74770100 | select count(*) from t                         | 
|        3 |  0.00004200 | show prifile for query 2                       | 
|        4 | 34.30410100 | insert into t(username) select username from t | 
|        5 |  1.50563800 | select count(*) from t                         | 
+----------+-------------+------------------------------------------------+
5 rows in set (0.00 sec)

mysql> show profile cpu,block io,memory,swaps,context switches,source for query 5;
……
mysql> update t set username = 'waill';
Query OK, 4194304 rows affected (44.82 sec)
Rows matched: 4194304  Changed: 4194304  Warnings: 0

mysql> show profiles;
+----------+-------------+------------------------------------------------+
| Query_ID | Duration    | Query                                          |
+----------+-------------+------------------------------------------------+
|        1 |  0.02717000 | show tables                                    | 
|        2 |  0.74770100 | select count(*) from t                         | 
|        3 |  0.00004200 | show prifile for query 2                       | 
|        4 | 34.30410100 | insert into t(username) select username from t | 
|        5 |  1.50563800 | select count(*) from t                         | 
|        6 | 44.82054700 | update t set username = 'waill'                | 
+----------+-------------+------------------------------------------------+
6 rows in set (0.00 sec)

mysql> show profile cpu,block io,memory,swaps,context switches,source for query 6;
posted on 2016-01-06 19:12  duanxz  阅读(1427)  评论(0编辑  收藏  举报