[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列值翻看源码 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高可用的心跳检测场景这里,就掉坑里了。