沃趣科技 罗小波
导读
1、故事背景
2、复现与剖析
3、解决方法
4、总结
1、故事背景在开始之前，先列出数据库的运行环境信息操作系统：redhat 7.2 x8_64文件系统：xfs数据库版本：MySQL 5.7.17主机配置：
* CPU：32 vcpus
* 内存：128 G
* 磁盘：单盘intel SSD 320G（只存放mysql的data和binlog）主要配置参数设置：innodb_buffer_pool_size = 96G，innodb_log_file_size = 2G，innodb_flush_method = O_DIRECT，sync_binlog = 1，innodb_flush_log_at_trx_commit = 1，innodb_thread_concurrency = 32,innodb_io_capacity = 20000，innodb_read_io_threads = 4，innodb_write_io_threads = 12，transaction_isolation = READ-COMMITTED，performance_schema=ON，binlog_rows_query_log_events=ON该实例接入了高可用机制：HA心跳探测机制60S内发现实例持续探测失败时（每5秒探测一次），直接尝试关闭探测失败的MySQL实例和主机，进行高可用切换故事情节：前些天某客户反馈一个诡异的问题，一个MySQL实例一会可访问，一会不可访问，查看相关日志发现该实例反复执行高可用切换，在进行初略排查时，通过监控发现服务器故障时刻磁盘负载都较高，但是并没有完全用满。而在高可用切换之前，数据库中跑着一些insert…select语句和大量心跳检测语句，而心跳检测语句与业务表是独立的，且心跳检测语句只固定更新一行数据，怎么会被阻塞一堆心跳检测语句呢 ？经过了一番折腾总算把原因找到了，具体过程请看下文！2、复现与剖析
经过初略的分析，虽然业务SQL和心跳SQL操作的是不同的表，不会出现锁等待问题，但是从show processlist;的结果来看，业务SQL执行时间最长，而且不断有新的心跳语句被阻塞（当然，这里要先关掉HA的切换机制，否则待会复现操作时，过了60S就可能被切换了），看起来阻塞心跳SQL的很可能就是业务SQL。而且这些业务SQL操作的数据量多达3千万行（因为是insert…select语句，所以从慢日志或者innodb_trx表、sys.session视图中查看到的数据量实际上多达6KW，翻倍了）。但是两者之间有具体有什么关联无法直观地看出来。我们按照如下步骤进行了复现：
2.1. 首先按照线上环境标准准备好复现环境，搭建了一台测试机
2.2. 创建一张心跳表，插入一行数据
点击(此处)折叠或打开
root@localhost :test:33: > CREATE TABLE `xx_heartbeat` (
`server_id` int(10) unsigned NOT NULL,
`hb_time` datetime NOT NULL,
PRIMARY KEY (`server_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin;
root@localhost :test:33: > insert into xx_heartbeat values(@@server_id,now());
root@localhost :test:33: > select * from xx_heartbeat;
+-----------+---------------------+
| server_id | hb_time |
+-----------+---------------------+
| 3306103 | 2017-10-11 12:33:26 |
+-----------+---------------------+
2 rows in set (0.00 sec)
2.3. 打开performance_schema中的等待事件采集(为了省事，这里使用sys schema下的函数操作，而不使用UPDATE语句直接修改performance_schema的配置表)
点击(此处)折叠或打开
root@localhost :test:34: > use sys
Database changed
root@localhost : sys:36: > call ps_setup_enable_instrument('wait');
+-------------------------+
| summary |
+-------------------------+
| Enabled 303 instruments |
+-------------------------+
1 row in set (0.04 sec)
Query OK, 0 rows affected (0.04 sec)
root@localhost : sys:36: > call ps_setup_enable_consumer('wait');
+---------------------+
| summary |
+---------------------+
| Enabled 3 consumers |
+---------------------+
1 row in set (0.01 sec)
Query OK, 0 rows affected (0.01 sec)
2.4. 开4个MySQL会话连接，依次对4张不同的表执行insert…select操作，表数据量都为3KW（测试数据为使用sysbench造的4张3KW数据的表）
点击(此处)折叠或打开
# 会话1
ADMIN@127.0.0.1 : (none):15: > use sbtest;
Database changed
ADMIN@127.0.0.1 : sbtest:37: > insert sbtest1(k,c,pad) select k,c,pad from sbtest1;
# 会话2
ADMIN@127.0.0.1 : (none):15: > use sbtest;
Database changed
ADMIN@127.0.0.1 : sbtest:37: > insert sbtest3(k,c,pad) select k,c,pad from sbtest3;
# 会话3
ADMIN@127.0.0.1 : (none):18: > use sbtest;
Database changed
ADMIN@127.0.0.1 : sbtest:37: > insert sbtest2(k,c,pad) select k,c,pad from sbtest2;
# 会话4
ADMIN@127.0.0.1 : (none):18: > use sbtest;
Database changed
ADMIN@127.0.0.1 : sbtest:37: > insert sbtest4(k,c,pad) select k,c,pad from sbtest4
2.5. 对心跳表进行更新，持续间隔每5秒一次执行，数十分钟之后，发现心跳SQL被阻塞了，如果HA切换机制没关，阻塞心跳SQL超过60S就会发生切换了，关闭HA切换机制之后，自动心跳会停止检测，所以这里人工模拟了一条心跳SQL，使用脚本循环每5秒更新一次，脚本在发现有阻塞时也会同时打印show processlist和sys.session视图信息，脚本链接：http://5d096a11.wiz03.com/share/s/1t2mEh0a-kl_2c2NZ33kSiac2wQRmx1ykAEE23yLIT3aKVmx)
点击(此处)折叠或打开
# 心跳SQL语句（可手工每5秒执行这句，不过肯定手会酸。。不过为了方便大家阅读，在复现过程中采用了用脚本持续检测，发现有语句阻塞时立即手工方式执行心跳语句，以方便截取）
ADMIN@127.0.0.1 :test:01: > update xx_heartbeat set hb_time=now() where server_id=@@server_id;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1Changed: 0Warnings: 0
ADMIN@127.0.0.1 :test:01: > update xx_heartbeat set hb_time=now() where server_id=@@server_id
2.6. 立即新开一个会话连接查看数据库正在做什么，可以发现4个会话的insert…select语句，以及心跳SQL update xx_heartbeat…
点击(此处)折叠或打开
ADMIN@127.0.0.1 : sys:25: > show processlist;
+-----+-------+--------------------+--------+---------+------+-----------+----------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-------+--------------------+--------+---------+------+-----------+----------------------------------------------------------------------+
| 25 | ADMIN | 127.0.0.1:35458 | sys | Query | 0 | starting | show processlist |
| 26 | ADMIN | 127.0.0.1:35459 | sbtest | Query | 1353 | query end | insert sbtest1(k,c,pad) select k,c,pad from sbtest1 |
| 27 | ADMIN | 127.0.0.1:35460 | sbtest | Query | 1352 | query end | insert sbtest3(k,c,pad) select k,c,pad from sbtest3 |
| 30 | ADMIN | 127.0.0.1:35463 | sbtest | Query | 1352 | query end | insert sbtest2(k,c,pad) select k,c,pad from sbtest2 |
| 31 | ADMIN | 127.0.0.1:35464 | sbtest | Query | 1351 | query end | insert sbtest4(k,c,pad) select k,c,pad from sbtest4 |
| 52 | ADMIN | 127.0.0.1:35485 | test | Query | 62 | query end | update xx_heartbeat set hb_time=now() where server_id=@@server_id |
| 151 | qfha | 10.10.40.167:51328 | NULL | Query | 562 | starting | SHOW BINARY LOGS |
......
| 160 | qfha | 10.10.40.167:51337 | NULL | Query | 22 | starting | SHOW BINARY LOGS |
+-----+-------+--------------------+--------+---------+------+-----------+----------------------------------------------------------------------+
16 rows in set (0.00 sec)
2.7. 查看服务器负载情况怎样
点击(此处)折叠或打开
# top
top - 22:51:21 up 3 days, 6:54, 9 users, load average: 5.74, 3.39, 1.70
Tasks: 980 total, 1 running, 979 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.4%us, 0.4%sy, 0.0%ni, 97.3%id, 1.9%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 131804428k total, 129297568k used, 2506860k free, 282052k buffers
Swap: 7974908k total, 106080k used, 7868828k free, 33743992k cached
PID USERPRNIVIRTRES SHR S %CPU %MEMTIME+ COMMAND
22080 mysql200 86.1g71g12m S 23.8 57.0 602:42.90 mysqld
29121 qemu200 17.5g 8.2g 6160 S6.96.5 140:51.21 qemu-kvm
20475 root200000 S0.70.00:28.71 xfs-cil/dm-6
18272 root200 15692 1952924 R0.30.00:00.33 top
1 root200 19356 1408 1228 S0.00.00:02.14 init
2 root200000 S0.00.00:00.01 kthreadd
3 rootRT0000 S0.00.00:00.28 migration/0
......
# free
#free -m
totalusedfreesharedbufferscached
Mem: 1287151216167099027528429
-/+ buffers/cache: 9291135803
Swap: 7787887699
# vmstat
[root@10-10-66-229 ~]# vmstat 1 10
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
rbswpdfreebuffcache si sobibo in cs us sy id wa st
2190392 2484712 281996 33758712000 266326 14803 1971791 8730
7190392 2454332 281996 33787004000 263063 14746 18893 101 8720
4 1090392 2427820 281996 33814484000 266977 13522 18440 101 8720
4090392 2399888 281996 33840928000 254064 14727 18820 101 8720
4190392 2373260 281996 33865532000 255281 15479 19072 100 8820
4190392 2344072 281996 338940360016 261650 13296 18970 100 8720
5090392 2316840 281996 33920892000 253947 12292 18442 101 8820
4090392 2289436 281996 33947748000 273755 13894 19790 101 8730
4090392 2258064 281996 33977544000 265602 12351 18488 100 8720
5190392 2230940 281996 34005292000 269967 12720 1943990 8820
......
# iostat
[root@10-10-66-229 ~]# vmstat -x 1 10
......
avg-cpu: %user%nice %system %iowait%steal%idle
10.280.000.502.510.0086.72
Device: rrqm/swrqm/sr/sw/srsec/swsec/s avgrq-sz avgqu-szawaitsvctm%util
sdc0.001031.000.00 6041.000.00 537654.0089.0013.202.190.1694.10
......
avg-cpu: %user%nice %system %iowait%steal%idle
9.830.000.532.540.0087.10
Device: rrqm/swrqm/sr/sw/srsec/swsec/s avgrq-sz avgqu-szawaitsvctm%util
sdc0.00891.000.00 6034.000.00 524171.0086.8712.782.120.1694.70
......
2.8. 从2.6与2.7步骤中查看到的信息来说，服务器的CPU和内存并不是瓶颈，磁盘负载虽然较高且偶尔会用到swap且有2~3%左右的IOWAIT，但是也不至于完全堵死一条单行更新的心跳SQL，而且业务SQL与心跳SQL是不同的表，也不存在表锁和事务锁相互阻塞的问题（使用sys.innodb_lock_waits视图查过，锁等待信息为空）。而从mysql的show processlist信息来看，看不出这些SQL有什么关联，只能看到这些SQL处于query end的状态时间比较长，明显不正常，另外还有一些show binary logs语句 ，该语句是监控系统监控binlog的大小使用的语句，而且这个语句不断增多，看起来像是binlog的访问出现了问题
2.9. 这个时候，通常使用的排查手段已经相形见拙了，我们启用sys schema，新开一个会话连接，使用session视图来查查这些活跃会话正在执行的SQL到底正在做什么?
点击(此处)折叠或打开
ADMIN@127.0.0.1 : sys:25: > select * from session where conn_id!=connection_id()\G;
*************************** 1. row ***************************
thd_id: 60
conn_id: 26
user: ADMIN@127.0.0.1
db: sbtest
command: Query
state: query end
time: 6355
current_statement: insert sbtest1(k,c,pad) select k,c,pad from sbtest1# 操作sbtest1表的业务SQL
statement_latency: 22.58 m
progress: NULL
lock_latency: 1.25 ms
rows_examined: 60000000
rows_sent: 0
rows_affected: 0
tmp_tables: 1
tmp_disk_tables: 1
full_scan: YES
last_statement: NULL
last_statement_latency: NULL
current_memory: 0 bytes
last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done# 发现连接ID为26的会话执行insert...select语句时在等待这个事件(binlog的COND_done互斥对象)
last_wait_latency: Still Waiting#该字段值为"Still Waiting"表示这个线程目前一直在等待last_wait字段显示的事件
source: binlog.cc:1949#发生等待事件的源码文件和代码行数在这里
trx_latency: NULL
trx_state: NULL
trx_autocommit: NULL
pid: 4571
program_name: mysql
*************************** 2. row ***************************
thd_id: 61
conn_id: 27
......
current_statement: insert sbtest3(k,c,pad) select k,c,pad from sbtest3
statement_latency: 22.57 m
......
last_wait: wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log # 发现连接ID为27的会话执行insert...select语句时在等待这个事件（binlog的LOCK_log互斥锁）
last_wait_latency: Still Waiting # 解释同第一行信息相同字段
source: binlog.cc:8587# 解释同第一行信息相同字段
......
*************************** 3. row ***************************
thd_id: 64
conn_id: 30
......
current_statement: insert sbtest2(k,c,pad) select k,c,pad from sbtest2 #操作sbtest2表的业务SQL
statement_latency: 22.57 m
......
last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done# 发现连接ID为30的会话执行insert...select语句时在等待这个事件(binlog的COND_done对象)
last_wait_latency: Still Waiting # 解释同第一行信息相同字段
source: binlog.cc:1949# 解释同第一行信息相同字段
......
*************************** 4. row ***************************
thd_id: 65
conn_id: 31
user: ADMIN@127.0.0.1
db: sbtest
command: Query
state: query end
time: 6353
current_statement: insert sbtest4(k,c,pad) select k,c,pad from sbtest4 #操作sbtest4表的业务SQL
statement_latency: 22.55 m
progress: NULL
lock_latency: 1.55 ms
rows_examined: 60000000
rows_sent: 0
rows_affected: 0
tmp_tables: 1
tmp_disk_tables: 1
full_scan: YES
last_statement: NULL
last_statement_latency: NULL
current_memory: 0 bytes
# 发现连接ID为31的会话执行insert...select语句时在等待这个事件(正在执行binlog的文件IO操作，说明在写binlog cache到binlog file，但这里只是写到文件系统的buffer，并不是sync)
last_wait: wait/io/file/sql/binlog
last_wait_latency: Still Waiting # 解释同第一行信息相同字段
source: mf_iocache.c:1566 # 解释同第一行信息相同字段
trx_latency: NULL
trx_state: NULL
trx_autocommit: NULL
pid: 4881
program_name: mysql
......
*************************** 5. row ***************************
thd_id: 185
conn_id: 151
user: qfha@10.10.40.167
db: sys
command: Query
state: starting
time: 564
current_statement: SHOW BINARY LOGS
statement_latency: 9.40 m
progress: NULL
lock_latency: 0 ps
rows_examined: 0
rows_sent: 0
rows_affected: 0
tmp_tables: 0
tmp_disk_tables: 0
full_scan: NO
last_statement: NULL
last_statement_latency: NULL
current_memory: 0 bytes
last_wait: wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log
last_wait_latency: Still Waiting
source: rpl_master.cc:707
trx_latency: NULL
trx_state: NULL
trx_autocommit: NULL
pid: NULL
program_name: NULL
*************************** 6. row ***************************
......
*************************** 11. row ***************************
thd_id: 86
conn_id: 52
user: ADMIN@127.0.0.1
db:test
command: Query
state: query end
time: 244
current_statement: update xx_heartbeat set hb_ ... () where server_id=@@server_id#操作心跳表的SQL
statement_latency: 1.07 m
progress: NULL
lock_latency: 219.00 us
rows_examined: 1
rows_sent: 0
rows_affected: 0
tmp_tables: 0
tmp_disk_tables: 0
full_scan: NO
last_statement: NULL
last_statement_latency: NULL
current_memory: 0 bytes
last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done# 发现连接ID为52的会话执行心跳SQL语句时在等待这个事件
last_wait_latency: Still Waiting# 解释同第一行信息相同字段
source: binlog.cc:1949# 解释同第一行信息相同字段
trx_latency: NULL
trx_state: NULL
trx_autocommit: NULL
pid: 6772
program_name: mysql
*************************** 12. row ***************************
......
15 rows in set (0.15 sec)
2.10. 从2.9步骤中的信息来看，基本可以确定是因为写binlog不能及时响应的问题导致的，但是具体是binlog的什么问题呢？跟心跳SQL被阻塞又有什么关系？这个时候我们在以上所有SQL正常执行完成之后（等待时间大约几分钟，超过了60S的高可用切换时间），解析了包含以上业务SQL和心跳SQL的所有binlog文件进行分析（binlog大约有22G），查看这些语句的提交先后顺序，发现都是在同一个group 里，并且心跳SQL排在了业务SQL最后面，详情如下：
点击(此处)折叠或打开
[root@10-10-66-229 binlog]# mysqlbinlog -vv mysql-bin.000175|grep -E 'insert sbtest|insert into sbtest|last_committed|update xx_heartbeat|GTID_NEXT' > a.sql
[root@10-10-66-229 binlog]# cat a.sql
......
#171011 15:01:42 server id 3306103end_log_pos 29975 CRC32 0x85a80516GTIDlast_committed=76sequence_number=77
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90292'/*!*/;
# update xx_heartbeat set hb_time=now() where server_id=@@server_id
#171011 15:01:43 server id 3306103end_log_pos 30366 CRC32 0x14c9d915GTIDlast_committed=77sequence_number=78
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90293'/*!*/;
# update xx_heartbeat set hb_time=now() where server_id=@@server_id
# 以下就是我们要找的关键信息，留意记录group 信息的event的时间，从这里可以看到insert...select语句发生的时间顺序按照表名排序\
# 依次sbtest1、sbtest3、sbtest2、sbtest4，xx_heartbeat表（与在客户端敲下SQL的时间顺序相同），从信息"last_committed=78"我们可以知道这些SQL都被放进了\
# 同一个队列里进行binlog提交，从信息"sequence_number=79"我们可以得知，操作表sbtest4的线程在binlog提交队列中的顺序最靠前，也就是说它是leader，其他的为follower
#171011 14:39:56 server id 3306103end_log_pos 30757 CRC32 0xb2c44222GTIDlast_committed=78sequence_number=79
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90294'/*!*/;
# insert sbtest4(k,c,pad) select k,c,pad from sbtest4 # 业务SQL
#171011 14:39:55 server id 3306103end_log_pos 1429482395 CRC32 0x00c7685dGTIDlast_committed=78sequence_number=80
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90295'/*!*/;
# insert sbtest3(k,c,pad) select k,c,pad from sbtest3 # 业务SQL
#171011 14:39:55 server id 3306103end_log_pos 2858934033 CRC32 0xb0e9f488GTIDlast_committed=78sequence_number=81
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90296'/*!*/;
# insert sbtest2(k,c,pad) select k,c,pad from sbtest2 # 业务SQL
#171011 14:39:54 server id 3306103end_log_pos 4288385671 CRC32 0x52cf3dfaGTIDlast_committed=78sequence_number=82
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90297'/*!*/;
# insert sbtest1(k,c,pad) select k,c,pad from sbtest1 # 业务SQL
#171011 16:21:45 server id 3306103end_log_pos 1422870013 CRC32 0xd3caff89GTIDlast_committed=78sequence_number=83
SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90298'/*!*/;
# 下面一句SQL即为被阻塞的心跳SQL，可以看到排在了前面几个业务SQL的后面，而前面几个业务SQL产生了大量的binlog数据，这些数据写到binlog文件中消耗了大量的时间\
# 而因为这句心跳SQL与前面几个业务SQL在同一个group中，必须等待前面几个业务SQL的binlog数据写完之后才能写binlog，所以，从这里就可以知道，\
# 心跳SQL就是因为在提交binlog阶段被业务SQL阻塞了，所以最终导致心跳SQL的事务无法提交
# update xx_heartbeat set hb_time=now() where server_id=@@server_id
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/
PS：到这里，我们已经知道了心跳SQL被阻塞的原因，但是在2.9步骤中，session视图输出行的last_wait列显示的事件代表什么含义呢？感兴趣的同学可以根据2.9步骤中信息行的source列值翻看源码
3、解决方法关于碰到类似的因为写binlog时互斥的原因导致毫不相干的表语句相互阻塞的问题的解决方法，需要自行根据业务需求进行分析，这里由于阻塞的是心跳SQL，而HA高可用程序依赖于心跳SQL的检测结果，对这个心跳SQL具有响应时间要求，必须按时返回结果，对于我们演示的这个场景而言，心跳SQL的作用就是检测MySQL实例是否存活、是否可写。so，对于心跳SQL的DML，记录binlog不是必须的，所以我们临时的解决办法就是：动态关闭心跳语句记录BINLOG的功能，就不会因为写binlog的原因被阻塞了，如下：
点击(此处)折叠或打开
set sql_log_bin=0;update xx_heartbeat set hb_time=now() where server_id=@@server_id
4、总结对于大事务的DML操作，从数据库的两大关键性能指标(并发数和响应时间)上考虑，强烈建议拆分数据量(例如使用limit按id进行拆分或者程序拆分)，虽然我们的开发规范上一再强调，但对于某些人来讲，他就认为慢点无所谓嘛，所以，在HA高可用的心跳检测场景这里，就掉坑里了
