应用示例荟萃 | performance_schema全方位介绍

经过前面6个篇幅的学习，相信大家对什么是performance_schema，已经初步形成了一个整体认识，但我想很多同行看完之前的文章之后可能还是一脸懵逼，今天就为大家带来performance_schema系列的最后一个篇章(全系共7个篇章)，在这一期里，我们将为大家列举数十个performance_schema应用示例。下面，请跟随我们一起开始performance_schema系统的学习之旅吧。

 

1.利用等待事件排查MySQL性能问题

通常，在生产服务器上线之前， 我们会对数据库服务器的硬件进行IO基准测试，对数据库进行增删改查的基准测试，建立基线参考数据，以便日后的服务器扩容或架构升级提供数据支撑。在基准测试规划时，我们通常需要选择一款基准测试软件（IO基准测试通常选择fio和iozone，MySQL数据库基准测试通常选择sysbench、tpcc-mysql、workbench等），在使用这些基准测试软件对服务器压测到一个极限值时，我们认为所得数据就是被测试服务器的最高性能。但这还不够，测试性能无法继续提升的原因还可能是因为你的服务器在BIOS设置、硬件搭配、操作系统参数、文件系统策略、数据库配置参数等方面不够优化。所以我们还需要借助一些性能排查手段来找出性能瓶颈所在，以使得我们对数据库服务器一旦上线之后可能的瓶颈点心中有数。以下我们以sysbench基准测试工具压测MySQL数据库为例，介绍如何使用performance_schema的等待事件来排查数据库性能瓶颈所在。 

首先，使用performance_schema配置表启用等待事件的采集与记录

# 启用所有的等待事件的instruments
admin@localhost : performance_schema 11:47:46> use performance_schema
Database changed
# 修改setup_instruments 表的enabled和timed字段为yes，表示启用对应的instruments
admin@localhost : performance_schema 11:48:05> update setup_instruments set enabled='yes',timed='yes' where name like 'wait/%';
Query OK, 269 rows affected (0.00 sec)
Rows matched: 323  Changed: 269  Warnings: 0
# 查看修改结果，enabled和timed字段为YES即表示当前instruments已经启用（但此时采集器并不会立即采集事件数据，需要保存这些等待事件的表--consumers，启用之后才会开始采集）
admin@localhost : performance_schema 11:49:40> select * from setup_instruments where name like 'wait/%';
+--------------------------------------------------------------------+---------+-------+
| NAME                                                              | ENABLED | TIMED |
+--------------------------------------------------------------------+---------+-------+
| wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_tc                          | YES    | YES  |
| wait/synch/mutex/sql/LOCK_des_key_file                            | YES    | YES  |
............
| wait/io/socket/sql/server_tcpip_socket                            | YES    | YES  |
| wait/io/socket/sql/server_unix_socket                              | YES    | YES  |
| wait/io/socket/sql/client_connection                              | YES    | YES  |
| wait/lock/metadata/sql/mdl                                        | YES    | YES  |
+--------------------------------------------------------------------+---------+-------+
323 rows in set (0.01 sec)
# 启用等待事件的consumers
admin@localhost : performance_schema 11:48:21> update setup_consumers set enabled='yes' where name like '%wait%';
Query OK, 3 rows affected (0.00 sec)
Rows matched: 3  Changed: 3  Warnings: 0
admin@localhost : performance_schema 11:49:20> select * from setup_consumers where name like '%wait%';
+---------------------------+---------+
| NAME                      | ENABLED |
+---------------------------+---------+
| events_waits_current      | YES    |
| events_waits_history      | YES    |
| events_waits_history_long | YES    |
+---------------------------+---------+
3 rows in set (0.00 sec)

然后，使用sysbench对数据库执行加压，并逐渐增加并发线程数，直到tps、qps不再随着线程数的增加而增加为止。

sysbench --test=oltp --db-driver=mysql --mysql-table-engine=innodb --mysql-host=10.10.10.10 --mysql-port=3306 --mysql-db=sbtest --mysql-user='qbench' --mysql-password='qbench' --test=/usr/share/doc/sysbench/tests/db/oltp.lua --oltp-table-size=5000000 --oltp-tables-count=8 --num-threads=16 --max-time=1800 --max-requests=0 --report-interval=1 run
............
[ 111s] threads: 16, tps: 52.99, reads/s: 668.93, writes/s: 171.98, response time: 629.52ms (95%)
[ 112s] threads: 16, tps: 42.00, reads/s: 650.93, writes/s: 202.98, response time: 688.46ms (95%)
............

从sysbench的输出结果中，我们可以看到在16个并发线程oltp压力下，tps只能跑到100不到，且延迟在600ms+，说明存在严重的性能瓶颈（或者在MySQL内部发生了严重的互斥等待，或者硬件设备严重的性能不足），现在，我们先使用操作系统命令查看硬件负载情况。

# top命令查看到CPU资源绝大部分都消耗在了%wa上，说明IO设备性能出现严重不足
[root@localhost ~]# top
top - 18:59:03 up  7:02,  3 users,  load average: 4.28, 5.82, 4.22
Tasks: 186 total,  1 running, 185 sleeping,  0 stopped,  0 zombie
Cpu0  :  4.1%us,  8.5%sy,  0.0%ni, 11.9%id, 75.4%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  4.0%us, 13.1%sy,  0.0%ni, 17.5%id, 65.0%wa,  0.0%hi,  0.3%si,  0.0%st
Cpu2  :  9.4%us, 32.1%sy,  0.0%ni,  2.3%id, 55.5%wa,  0.0%hi,  0.7%si,  0.0%st
Cpu3  :  3.0%us,  5.3%sy,  0.0%ni, 31.0%id, 60.0%wa,  0.0%hi,  0.7%si,  0.0%st
Mem:  8053664k total,  1684236k used,  6369428k free,    87868k buffers
Swap:  2031612k total,        0k used,  2031612k free,  150680k cached
# iostat命令查看磁盘负载，通过%util列可以看到，磁盘处于100%满负载状态
avg-cpu:  %user  %nice %system %iowait  %steal  %idle
      1.77    0.00    2.28  95.70    0.00    0.25
Device:        rrqm/s  wrqm/s    r/s    w/s  rsec/s  wsec/s avgrq-sz avgqu-sz  await  svctm  %util
dm-2              0.00    0.00  277.00  160.00  8864.00  2774.00    26.63    47.84  112.98  2.29 100.10
avg-cpu:  %user  %nice %system %iowait  %steal  %idle
      5.05    0.00  11.62  64.14    0.00  19.19
Device:        rrqm/s  wrqm/s    r/s    w/s  rsec/s  wsec/s avgrq-sz avgqu-sz  await  svctm  %util
dm-2              0.00    0.00  267.00  244.00  8544.00  4643.00    25.81    28.20  40.29  1.96 100.00

通过查询系统负载，一眼就可以看出来是由于磁盘性能严重不足导致的，但是，在数据库内部的事件信息是如何体现的呢（注意：如果你没有足够的performance_schema使用经验，此时是绝好的学习积累的机会，不要错过，也许哪一天操作系统负载并不能看出来端倪的时候，这些事件信息能帮上大忙）

# 为了方便查询等待事件统计，我们可以先创建一个视图，用于实时统计当前等待事件（非历史数据）
admin@localhost : performance_schema 12:14:14> create view sys.test_waits as select sum(TIMER_WAIT) as TIMER_WAIT,sum(NUMBER_OF_BYTES) as NUMBER_OF_BYTES, EVENT_NAME,OPERATION from events_waits_current where EVENT_NAME!='idle' group by EVENT_NAME,OPERATION;
Query OK, 0 rows affected (0.04 sec)
# 使用前面创建的视图进行查询，对这个视图查询结果进行降序排序查询。从下面的查询结果中，我们可以看到时间开销排名前5的有4个都是与IO相关的等待，剩下1个是binlog相关的互斥等待
admin@localhost : performance_schema 12:30:38> select sys.format_time(TIMER_WAIT),sys.format_bytes(NUMBER_OF_BYTES),EVENT_NAME,OPERATION from sys.test_waits where sys.format_time(TIMER_WAIT) not regexp 'ns|us' order by TIMER_WAIT desc;
+-----------------------------+-----------------------------------+------------------------------------------------+------------+
| sys.format_time(TIMER_WAIT) | sys.format_bytes(NUMBER_OF_BYTES) | EVENT_NAME                                    | OPERATION  |
+-----------------------------+-----------------------------------+------------------------------------------------+------------+
| 16.60 s                    | 224.00 KiB                        | wait/io/file/innodb/innodb_data_file          | read      |
| 16.05 s                    | 553 bytes                        | wait/io/table/sql/handler                      | fetch      |
| 1.96 s                      | NULL                              | wait/io/file/sql/binlog                        | sync      |
| 1.96 s                      | NULL                              | wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond | timed_wait |
| 1.85 s                      | 1.34 KiB                          | wait/io/file/sql/binlog                        | write      |
| 56.66 ms                    | NULL                              | wait/io/file/innodb/innodb_log_file            | sync      |
+-----------------------------+-----------------------------------+------------------------------------------------+------------+
6 rows in set (0.01 sec)
# 当然，你也可以直接查询events_waits_current表（返回数据行数可能比较多，且查询结果并没有做分组聚合，是逐行的事件记录数据）
admin@localhost : performance_schema 11:59:25> select THREAD_ID,EVENT_NAME,sys.format_time(TIMER_WAIT),INDEX_NAME,NESTING_EVENT_TYPE,OPERATION,NUMBER_OF_BYTES from events_waits_current where EVENT_NAME!='idle' order by TIMER_WAIT desc;
+-----------+------------------------------------------------+-----------------------------+------------+--------------------+------------+-----------------+
| THREAD_ID | EVENT_NAME                                    | sys.format_time(TIMER_WAIT) | INDEX_NAME | NESTING_EVENT_TYPE | OPERATION  | NUMBER_OF_BYTES |
+-----------+------------------------------------------------+-----------------------------+------------+--------------------+------------+-----------------+
|      115 | wait/io/table/sql/handler                      | 169.48 ms                  | PRIMARY    | STATEMENT          | fetch      |              39 |
|      115 | wait/io/file/innodb/innodb_data_file          | 169.48 ms                  | NULL      | WAIT              | read      |          16384 |
|      101 | wait/io/table/sql/handler                      | 93.76 ms                    | PRIMARY    | STATEMENT          | fetch      |              39 |
|      101 | wait/io/file/innodb/innodb_data_file          | 93.76 ms                    | NULL      | WAIT              | read      |          16384 |
|      111 | wait/io/file/innodb/innodb_data_file          | 73.08 ms                    | NULL      | STATEMENT          | read      |          16384 |
|      103 | wait/io/file/innodb/innodb_data_file          | 63.13 ms                    | NULL      | STATEMENT          | read      |          16384 |
|      106 | wait/io/file/innodb/innodb_data_file          | 53.24 ms                    | NULL      | STATEMENT          | read      |          16384 |
|      113 | wait/io/table/sql/handler                      | 51.90 ms                    | PRIMARY    | STATEMENT          | fetch      |              39 |
|      113 | wait/io/file/innodb/innodb_data_file          | 51.90 ms                    | NULL      | WAIT              | read      |          16384 |
|        49 | wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond | 27.48 ms                    | NULL      | STATEMENT          | timed_wait |            NULL |
............
57 rows in set (0.00 sec)

从上述等待事件的查询结果中，我们可以非常清晰地看到，事务大多数的延迟时间花在了等待IO上（主要是undo log、redo log，独立表空间文件，binlog的fetch和read系统调用），说明IO设备可能出现了严重的性能瓶颈，这里与操作系统命令查看到的磁盘性能严重不足相对应。

结论：通过以上测试数据表明，MySQL的性能严重低下的原因是因为磁盘性能严重不足成为了瓶颈（一般情况下，4个core的cpu在内存和磁盘不构成瓶颈的情况下可以达到800+ tps才可能会构成瓶颈）

针对IO性能不足，建议优化策略：

• 更换IO性能更好的设备

• 新增2个独立的相同设备，把MySQL 中的redo log、binlog、其他data file分别放在3个独立的IO设备上，以便数据库中的随机IO和顺序IO不会因为相互争抢资源而导致IO等待

PS：

当然，你也许会说，我们在这个案例里故意使用一台配置很差的服务器。是的没错。但我们可以去思考一个问题：performance_schema到底能够对我们使用MySQL提供多大帮助呢？对于目前来讲，互联网上并不能找到太多靠谱的performance_schema使用经验，需要我们不断地去挖掘。我们建议有条件的同行可以准备两台测试服务器(一台低配置，一台高配置服务器)，通过对比测试数据你就能得出performance_schema的使用经验了，正所谓没有对比就没有伤害。

 

2.锁问题排查

2.1 找出谁持有全局读锁

全局读锁通常是由flush table with read lock;这类语句添加，这类语句通常是在各种备份工具为了拿到一致性备份时使用，另外，在具有主从复制架构的环境中做主备切换时也常常使用，除了这两种情况之外，还有一种情况也是最难排查的一种情况，那就是线上系统权限约束不规范的时候，各种人员使用的数据库帐号都具有RELOAD权限时，都可以对数据库加全局读锁。 

在MySQL 5.7之前的版本，要排查谁持有全局读锁通常在数据库层面是很难直接查询到有用数据（innodb_locks表也只能记录innodb层的锁信息，而全局读锁是server层的锁，所以也无法查询到），从MySQL 5.7开始提供表performance_schema.metadata_locks表记录一些Server层的锁信息（包括全局读锁和MDL锁等），下面我们通过一个示例来演示然后使用performance_schema来找出谁持有全局读锁。

首先，开启第一个会话，执行全局读锁。

# 执行加锁语句
root@localhost : sbtest 12:28:30> flush table with read lock;
Query OK, 0 rows affected (0.00 sec)
# 查询以下加锁线程的process id，以便后续排查过程好对应
root@localhost : sbtest 12:31:48> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
| 4 |
+-----------------+
1 row in set (0.00 sec)

现在，我们开启第二个会话执行任意可能对数据造成修改的语句，我们就以update操作为例吧。

root@localhost : sbtest 12:42:36> use sbtest
Database changed
root@localhost : sbtest 12:42:38> select * from sbtest1 limit 1\G;
*************************** 1. row ***************************
id: 21
k: 2483476
c: 09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849
pad: 96813293060-05308009118-09223341195-19224109585-45598161848
1 row in set (0.00 sec)
ERROR: 
No query specified
root@localhost : sbtest 12:42:39> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
| 5 |
+-----------------+
1 row in set (0.00 sec)
root@localhost : sbtest 12:42:44> update sbtest1 set pad='xxx' where id=21;  操作被阻塞

现在，我们开启第三个会话，开始使用一些手段进行排查。

root@localhost : (none) 12:42:25> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
| 16 |
+-----------------+
1 row in set (0.00 sec)
# 查询processlist信息，这里只能看到processid为5的线程State为Waiting for global read lock，表示正在等待全局读锁
root@localhost : (none) 12:43:11> show processlist;
+----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------------------------------+
| 3 | qfsys | 192.168.2.168:41042 | NULL | Binlog Dump | 11457 | Master has sent all binlog to slave; waiting for more updates | NULL |
| 4 | root | l