一、故事背景
在开始之前,先列出数据库的运行环境信息
操作系统:redhat 7.2 x8_64
文件系统:xfs
数据库版本:MySQL 5.7.17
主机配置:
* CPU:32 vcpus
* 内存:128 G
* 磁盘:sandisk 单盘 SSD lvm 200G(只存放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语句和大量心跳检测语句,而心跳检测语句与业务表是独立的,且心跳检测语句只固定更新一行数据,怎么会被阻塞一堆心跳检测语句呢 ?经过了一番折腾总算把原因找到了,具体过程请看下文。
二、复现与剖析
经过初略的分析,虽然业务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