MySQL自带性能监控工具

MySQL自带了一些工具可以分析SQL执行的情况，这里简单总结一下常用的工具。

References

这些东西资料比较少，网上的文章也大多是摘录书中的，因此最新的尽量以官网为准。

  • SHOW PROFILE

SHOW PROFILE命令是在MySQL 5.1以后的版本中引入的，默认是禁用的，但可以通过服务器变量在会话（连接）级别动态地修改。
执行:

mysql> set profiling = 1;

然后，在服务器上执行的所有语句，都会测量其耗费的时间和其他一些查询执行状态变更相关的数据。这个功能有一定的作用，而且最初的设计功能更强大，但未来版本中可能会被Performance Schema所取代。尽管如此，这个工具最有用的作用还是在语句执行期间剖析服务器的具体工作。
当一条查询提交给服务器时，此工具会记录剖析信息到一张临时表，并且给查询赋予一个从1开始的整数标识符。
如下所示，在开启profile后执行了3条查询SQL，查询profile信息即可得到SQL执行耗费的时间。

mysql> show profiles;
+----------+------------+----------------------------+
| Query_ID | Duration   | Query                      |
+----------+------------+----------------------------+
|        1 | 0.00024350 | select * from balance      |
|        2 | 0.00215230 | select * from user         |
|        3 | 0.00028760 | select * from cst_customer |
+----------+------------+----------------------------+
3 rows in set (0.000 sec)

如需对某一条SQL详细分析，则可使用对应的Query_ID查询，也可以添加要profile的类型:

mysql> show profile for query 2;
+------------------------+----------+
| Status                 | Duration |
+------------------------+----------+
| Starting               | 0.000050 |
| checking permissions   | 0.000006 |
| Opening tables         | 0.000019 |
| After opening tables   | 0.000005 |
| System lock            | 0.000004 |
| table lock             | 0.000007 |
| Opening tables         | 0.000016 |
| After opening tables   | 0.000003 |
| System lock            | 0.000003 |
| table lock             | 0.000023 |
| Unlocking tables       | 0.000003 |
| closing tables         | 0.000010 |
| init                   | 0.000016 |
| Optimizing             | 0.000007 |
| Statistics             | 0.000012 |
| Preparing              | 0.000012 |
| Executing              | 0.000003 |
| Sending data           | 0.001883 |
| End of update loop     | 0.000010 |
| Query end              | 0.000003 |
| Commit                 | 0.000005 |
| closing tables         | 0.000003 |
| Unlocking tables       | 0.000003 |
| closing tables         | 0.000007 |
| Starting cleanup       | 0.000004 |
| Freeing items          | 0.000006 |
| Updating status        | 0.000028 |
| Reset for next command | 0.000003 |
+------------------------+----------+
28 rows in set (0.000 sec)

mysql> show profile cpu for query 2;
+------------------------+----------+----------+------------+
| Status                 | Duration | CPU_user | CPU_system |
+------------------------+----------+----------+------------+
| Starting               | 0.000050 | 0.000000 |   0.000000 |
| checking permissions   | 0.000006 | 0.000000 |   0.000000 |
| Opening tables         | 0.000019 | 0.000000 |   0.000000 |
| After opening tables   | 0.000005 | 0.000000 |   0.000000 |
| System lock            | 0.000004 | 0.000000 |   0.000000 |
| table lock             | 0.000007 | 0.000000 |   0.000000 |
| Opening tables         | 0.000016 | 0.000000 |   0.000000 |
| After opening tables   | 0.000003 | 0.000000 |   0.000000 |
| System lock            | 0.000003 | 0.000000 |   0.000000 |
| table lock             | 0.000023 | 0.000000 |   0.000000 |
| Unlocking tables       | 0.000003 | 0.000000 |   0.000000 |
| closing tables         | 0.000010 | 0.000000 |   0.000000 |
| init                   | 0.000016 | 0.000000 |   0.000000 |
| Optimizing             | 0.000007 | 0.000000 |   0.000000 |
| Statistics             | 0.000012 | 0.000000 |   0.000000 |
| Preparing              | 0.000012 | 0.000000 |   0.000000 |
| Executing              | 0.000003 | 0.000000 |   0.000000 |
| Sending data           | 0.001883 | 0.000000 |   0.000000 |
| End of update loop     | 0.000010 | 0.000000 |   0.000000 |
| Query end              | 0.000003 | 0.000000 |   0.000000 |
| Commit                 | 0.000005 | 0.000000 |   0.000000 |
| closing tables         | 0.000003 | 0.000000 |   0.000000 |
| Unlocking tables       | 0.000003 | 0.000000 |   0.000000 |
| closing tables         | 0.000007 | 0.000000 |   0.000000 |
| Starting cleanup       | 0.000004 | 0.000000 |   0.000000 |
| Freeing items          | 0.000006 | 0.000000 |   0.000000 |
| Updating status        | 0.000028 | 0.000000 |   0.000000 |
| Reset for next command | 0.000003 | 0.000000 |   0.000000 |
+------------------------+----------+----------+------------+
28 rows in set (0.000 sec)

剖析报告给出了查询执行的每个步骤及其花费的时间，看结果很难快速地确定哪个步骤花费的时间最多。因为输出是按照执行顺序排序，而不是按花费的时间排序的——而实际上我们更关心的是花费了多少时间，这样才能知道哪些开销比较大。但不幸的是无法通过诸如ORDER BY之类的命令重新排序。如果要按照花费大小排序，就不能使用show prifile命令，而是直接使用INFORMATION_SCHEMA中对应的表。

mysql> set @query_id = 2;
Query OK, 0 rows affected (0.001 sec)

mysql> 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.001883 | 87.42 |     1 | 0.0018830000 |
| Starting               | 0.000050 |  2.32 |     1 | 0.0000500000 |
| Opening tables         | 0.000035 |  1.62 |     2 | 0.0000175000 |
| table lock             | 0.000030 |  1.39 |     2 | 0.0000150000 |
| Updating status        | 0.000028 |  1.30 |     1 | 0.0000280000 |
| closing tables         | 0.000020 |  0.93 |     3 | 0.0000066667 |
| init                   | 0.000016 |  0.74 |     1 | 0.0000160000 |
| Preparing              | 0.000012 |  0.56 |     1 | 0.0000120000 |
| Statistics             | 0.000012 |  0.56 |     1 | 0.0000120000 |
| End of update loop     | 0.000010 |  0.46 |     1 | 0.0000100000 |
| After opening tables   | 0.000008 |  0.37 |     2 | 0.0000040000 |
| System lock            | 0.000007 |  0.32 |     2 | 0.0000035000 |
| Optimizing             | 0.000007 |  0.32 |     1 | 0.0000070000 |
| checking permissions   | 0.000006 |  0.28 |     1 | 0.0000060000 |
| Unlocking tables       | 0.000006 |  0.28 |     2 | 0.0000030000 |
| Freeing items          | 0.000006 |  0.28 |     1 | 0.0000060000 |
| Commit                 | 0.000005 |  0.23 |     1 | 0.0000050000 |
| Starting cleanup       | 0.000004 |  0.19 |     1 | 0.0000040000 |
| Executing              | 0.000003 |  0.14 |     1 | 0.0000030000 |
| Reset for next command | 0.000003 |  0.14 |     1 | 0.0000030000 |
| Query end              | 0.000003 |  0.14 |     1 | 0.0000030000 |
+------------------------+----------+-------+-------+--------------+
21 rows in set (0.001 sec)

效果好多了！通过这个结果可以很容易看到查询时间主要消耗在哪些操作上。尽管剖析报告能帮助我们定位到哪些活动花费了最多的时间，但并不会告诉我们为什么会这样。要弄清楚为什么复制数据到临时表要花费这么多时间，就需要深入下去。
注：在MySQL官网上已将SHOW PROFILE和SHOW PROFILES标记为deprecated，可能会在未来的版本中移除，替代品是Performance Schema。

  • Performance Schema

提供了一种在数据库运行时实时检查server的内部执行情况的方法。performance_schema 数据库中的表使用performance_schema存储引擎。该数据库主要关注数据库运行过程中的性能相关的数据，与information_schema不同，information_schema主要关注server运行过程中的元数据信息。
在mysql的5.7版本中，性能模式是默认开启的，如果想要显式的关闭的话需要修改配置文件，不能直接进行修改，会报错Variable 'performance_schema' is a read only variable。

-- 查看performance_schema的属性
mysql> SHOW VARIABLES LIKE 'performance_schema';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| performance_schema | ON    |
+--------------------+-------+
1 row in set (0.01 sec)

-- 在配置文件中修改performance_schema的属性值，on表示开启，off表示关闭
[mysqld]
performance_schema=ON

-- 切换数据库
use performance_schema;

-- 查看当前数据库下的所有表,会看到有很多表存储着相关的信息
show tables;

-- 可以通过show create table tablename来查看创建表的时候的表结构
mysql> show create table setup_consumers;
+-----------------+---------------------------------
| Table           | Create Table                    
+-----------------+---------------------------------
| setup_consumers | CREATE TABLE `setup_consumers` (
  `NAME` varchar(64) NOT NULL,                      
  `ENABLED` enum('YES','NO') NOT NULL               
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8 |  
+-----------------+---------------------------------
1 row in set (0.00 sec)

数据库刚刚初始化并启动时，并非所有instruments(事件采集项，在采集项的配置表中每一项都有一个开关字段，或为YES，或为NO)和consumers(与采集项类似，也有一个对应的事件类型保存表配置项，为YES就表示对应的表保存性能数据，为NO就表示对应的表不保存性能数据)都启用了，所以默认不会收集所有的事件，可能你需要检测的事件并没有打开，需要进行设置，可以使用如下两个语句打开对应的instruments和consumers（行计数可能会因MySQL版本而异)。

-- 打开等待事件的采集器配置项开关，需要修改setup_instruments配置表中对应的采集器配置项
UPDATE setup_instruments SET ENABLED = 'YES', TIMED = 'YES'where name like 'wait%';

-- 打开等待事件的保存表配置开关，修改setup_consumers配置表中对应的配置项
UPDATE setup_consumers SET ENABLED = 'YES'where name like '%wait%';

-- 当配置完成之后可以查看当前server正在做什么，可以通过查询events_waits_current表来得知，该表中每个线程只包含一行数据，用于显示每个线程的最新监视事件
select * from events_waits_current\G
*************************** 1. row ***************************
            THREAD_ID: 11
             EVENT_ID: 570
         END_EVENT_ID: 570
           EVENT_NAME: wait/synch/mutex/innodb/buf_dblwr_mutex
               SOURCE: 
          TIMER_START: 4508505105239280
            TIMER_END: 4508505105270160
           TIMER_WAIT: 30880
                SPINS: NULL
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
           INDEX_NAME: NULL
          OBJECT_TYPE: NULL
OBJECT_INSTANCE_BEGIN: 67918392
     NESTING_EVENT_ID: NULL
   NESTING_EVENT_TYPE: NULL
            OPERATION: lock
      NUMBER_OF_BYTES: NULL
                FLAGS: NULL
/*该信息表示线程id为11的线程正在等待buf_dblwr_mutex锁，等待事件为30880
属性说明：
    id:事件来自哪个线程，事件编号是多少
    event_name:表示检测到的具体的内容
    source:表示这个检测代码在哪个源文件中以及行号
    timer_start:表示该事件的开始时间
    timer_end:表示该事件的结束时间
    timer_wait:表示该事件总的花费时间
注意：_current表中每个线程只保留一条记录，一旦线程完成工作，该表中不会再记录该线程的事件信息
*/

/*
_history表中记录每个线程应该执行完成的事件信息，但每个线程的事件信息只会记录10条，再多就会被覆盖，*_history_long表中记录所有线程的事件信息，但总记录数量是10000，超过就会被覆盖掉
*/
select thread_id,event_id,event_name,timer_wait from events_waits_history order by thread_id limit 21;

/*
summary表提供所有事件的汇总信息，该组中的表以不同的方式汇总事件数据（如：按用户，按主机，按线程等等）。例如：要查看哪些instruments占用最多的时间，可以通过对events_waits_summary_global_by_event_name表的COUNT_STAR或SUM_TIMER_WAIT列进行查询（这两列是对事件的记录数执行COUNT（*）、事件记录的TIMER_WAIT列执行SUM（TIMER_WAIT）统计而来）
*/
SELECT EVENT_NAME,COUNT_STAR FROM events_waits_summary_global_by_event_name  ORDER BY COUNT_STAR DESC LIMIT 10;

/*
instance表记录了哪些类型的对象会被检测。这些对象在被server使用时，在该表中将会产生一条事件记录，例如，file_instances表列出了文件I/O操作及其关联文件名
*/
select * from file_instances limit 20;
  • SHOW PROCESSLIST

使用SHOW PROCESSLIST查看连接的线程个数，来观察是否有大量线程处于不正常的状态或者其他不正常的特征。例如查询很少会长时间处于“statistics”状态，这个状态一般是指服务器在查询优化阶段如何确定表关联的顺序——通常都是非常快的。另外，也很少会见到大量线程报告当前连接用户是“未经验证的用户（Unauthenticated user）”，这只是在连接握手的中间过程中的状态，当客户端等待输入用于登录的用户信息的时候才会出现。
使用SHOW PROCESSLIST命令时，在尾部加上\G可以垂直的方式输出结果，这样会将每一行记录的每一列都单独输出为一行：

mysql> show processlist;
+----+------+-----------------+--------------------+---------+------+----------+------------------+----------+
| Id | User | Host            | db                 | Command | Time | State    | Info             | Progress |
+----+------+-----------------+--------------------+---------+------+----------+------------------+----------+
|  3 | root | localhost:56662 | test               | Sleep   | 8325 |          | NULL             |    0.000 |
|  4 | root | localhost:56664 | test               | Sleep   | 8325 |          | NULL             |    0.000 |
|  5 | root | localhost:56700 | test               | Sleep   | 8336 |          | NULL             |    0.000 |
|  6 | root | localhost:56712 | performance_schema | Query   |    0 | starting | show processlist |    0.000 |
+----+------+-----------------+--------------------+---------+------+----------+------------------+----------+
4 rows in set (0.000 sec)

mysql> show processlist\G;
*************************** 1. row ***************************
      Id: 3
    User: root
    Host: localhost:56662
      db: test
 Command: Sleep
    Time: 8387
   State:
    Info: NULL
Progress: 0.000
*************************** 2. row ***************************
      Id: 4
    User: root
    Host: localhost:56664
      db: test
 Command: Sleep
    Time: 8387
   State:
    Info: NULL
Progress: 0.000
*************************** 3. row ***************************
      Id: 5
    User: root
    Host: localhost:56700
      db: test
 Command: Sleep
    Time: 8397
   State:
    Info: NULL
Progress: 0.000
*************************** 4. row ***************************
      Id: 6
    User: root
    Host: localhost:56712
      db: performance_schema
 Command: Query
    Time: 0
   State: starting
    Info: show processlist
Progress: 0.000
4 rows in set (0.000 sec)

ERROR: No query specified
属性含义
idsession id
User操作的用户
Host操作的主机
db操作的数据库
Command命令类型
Info详细的sql语句
Time命令执行时间
State命令执行状态

一般项目都会使用数据库连接池来控制连接。

标签: none

添加新评论

ali-01.gifali-58.gifali-09.gifali-23.gifali-04.gifali-46.gifali-57.gifali-22.gifali-38.gifali-13.gifali-10.gifali-34.gifali-06.gifali-37.gifali-42.gifali-35.gifali-12.gifali-30.gifali-16.gifali-54.gifali-55.gifali-59.gif

加载中……