利用sys schema解决一次诡异的语句hang问题

古城微笑少年丶 2022-06-07 06:43 197阅读 0赞

一、故事背景

在开始之前，先列出数据库的运行环境信息

操作系统：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
> 
> 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: 1  Changed: 0  Warnings: 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 USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            22080 mysql    20  0 86.1g  71g  12m S 23.8 57.0 602:42.90 mysqld                              29121 qemu      20  0 17.5g 8.2g 6160 S  6.9  6.5 140:51.21 qemu-kvm                          20475 root      20  0    0    0    0 S  0.7  0.0  0:28.71 xfs-cil/dm-6                                    18272 root      20  0 15692 1952  924 R  0.3  0.0  0:00.33 top                                          1 root      20  0 19356 1408 1228 S  0.0  0.0  0:02.14 init                                                  2 root      20  0    0    0    0 S  0.0  0.0  0:00.01 kthreadd                                                    3 root      RT  0    0    0    0 S  0.0  0.0  0:00.28 migration/0                                                ......
> 
>   
> 
> 
> \# memory  
> 
> 
> \#free -m
> 
>            total      used      free    shared    buffers    cached
> 
> Mem:        128715    121616      7099          0        275      28429
> 
> \-/+ buffers/cache:      92911      35803
> 
> Swap:        7787        88      7699
> 
>   
> 
> 
> \# vmstat
> 
> \[root@10-10-66-229 ~\]\# vmstat 1 10
> 
> procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
> 
> r  b  swpd  free  buff  cache  si  so    bi    bo  in  cs us sy id wa st
> 
> 2  1  90392 2484712 281996 33758712    0    0    0 266326 14803 19717  9  1 87  3  0  
> 
> 7  1  90392 2454332 281996 33787004    0    0    0 263063 14746 18893 10  1 87  2  0  
> 
> 4 10  90392 2427820 281996 33814484    0    0    0 266977 13522 18440 10  1 87  2  0  
> 
> 4  0  90392 2399888 281996 33840928    0    0    0 254064 14727 18820 10  1 87  2  0 
> 
> 4  1  90392 2373260 281996 33865532    0    0    0 255281 15479 19072 10  0 88  2  0 
> 
> 4  1  90392 2344072 281996 33894036    0    0    16 261650 13296 18970 10  0 87  2  0  
> 
> 5  0  90392 2316840 281996 33920892    0    0    0 253947 12292 18442 10  1 88  2  0  
> 
> 4  0  90392 2289436 281996 33947748    0    0    0 273755 13894 19790 10  1 87  3  0  
> 
> 4  0  90392 2258064 281996 33977544    0    0    0 265602 12351 18488 10  0 87  2  0
> 
> 5  1  90392 2230940 281996 34005292    0    0    0 269967 12720 19439  9  0 88  2  0
> 
> ......
> 
>   
> 
> 
> \# iostat
> 
> \[root@10-10-66-229 ~\]\# vmstat -x 1 10
> 
> ......
> 
> avg-cpu:  %user  %nice %system %iowait  %steal  %idle
> 
>          10.28    0.00    0.50    2.51    0.00  86.72
> 
> Device:        rrqm/s  wrqm/s    r/s    w/s  rsec/s  wsec/s avgrq-sz avgqu-sz  await  svctm  %util
> 
> sdc              0.00  1031.00    0.00 6041.00    0.00 537654.00    89.00    13.20    2.19  0.16  94.10
> 
> ......
> 
> avg-cpu:  %user  %nice %system %iowait  %steal  %idle
> 
>          9.83    0.00    0.53    2.54    0.00  87.10
> 
> Device:        rrqm/s  wrqm/s    r/s    w/s  rsec/s  wsec/s avgrq-sz avgqu-sz  await  svctm  %util
> 
> sdc              0.00  891.00    0.00 6034.00    0.00 524171.00    86.87    12.78    2.12  0.16  94.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 3306103  end\_log\_pos 29975 CRC32 0x85a80516  GTID    last\_committed=76      sequence\_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 3306103  end\_log\_pos 30366 CRC32 0x14c9d915  GTID    last\_committed=77      sequence\_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 3306103  end\_log\_pos 30757 CRC32 0xb2c44222  GTID    last\_committed=78      sequence\_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 3306103  end\_log\_pos 1429482395 CRC32 0x00c7685d    GTID    last\_committed=78      sequence\_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 3306103  end\_log\_pos 2858934033 CRC32 0xb0e9f488    GTID    last\_committed=78      sequence\_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 3306103  end\_log\_pos 4288385671 CRC32 0x52cf3dfa    GTID    last\_committed=78      sequence\_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 3306103  end\_log\_pos 1422870013 CRC32 0xd3caff89    GTID    last\_committed=78      sequence\_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列值翻看源码

三、解决方法

关于碰到类似的因为写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;

四、总  结

对于大事务的DML操作，从数据库的两大关键性能指标(并发数和响应时间)上考虑，强烈建议拆分数据量(例如使用limit按id进行拆分或者程序拆分)，虽然我们的开发规范上一再强调，但对于某些人来讲，他就认为慢点无所谓嘛，所以，在HA高可用的心跳检测场景这里，就掉坑里了。