标签：binlog log pos 主从 发送 mysql 日志 event 延迟
之所以进行这块内容的研究，主要针对之前遇到的两个未解的疑惑：
a． 线上有个系统，半同步状态经常从半同步变成异步，然后又马上恢复为半同步，具体原因未明，虽然之前也猜得八九不离十，但还是未完全确定。
b． 前段时间因为有业务场景需求，做了跨机房异步复制测试。当mysql写qps非常高的时候，发现很多日志还没有来得及发送到从库，也就是binlog日志在主库的产生速度大于传送到从库的速度，这个速度差一直存在，因此当主库在持续高压力地产生binlog的时候，越来越多的binlog没有传送到从库，但当时的网络流量也才18M/S左右（一主一从），从常规的知识认为，千兆的网络传送的速度可以达到100M，而当前的主从之间的binlog传送速度只达到了18M左右，原因是什么？ 是网络问题？ 还是其他原因。
1 主从复制原理
1.1 Dump线程与io线程
当主从复制关系建立之后，主库上有个dump线程，用来传送在主库产生的binlog日志的，而从库上的io线程，则用来接收由dump线程通过网络传送到从库的binlog日志，并负责将其写入relay log 中去。 这就是主从复制的机制， 同时，由于是异步复制，传送过程不需要ack的确认。
疑问也正在此处------因为是异步传输，如果单纯地理解为binlog文件直接网络传送，这个速度应该很快才是，但实际情况:在我们的测试环境中，binlog日志的传送速度才18M/s ，小于日志产生的22M/s左右的速度。 为什么只有这个速度，而没有把网络带宽用满？原因是什么？
1.2 日志传送细节
主从复制的结构中，主库上的dump线程跟从库上的io线程各自有一个，所以不存在多线程地并发发送跟接收的情况，只需要了解binlog dump线程的工作机制，就能了解所有的细节。
通过解析binlog文件，我们可以知道，一个事务可以包含多个event, 下面是一个最简单的事物的在binlog中所记录的信息：
# at 33580
#170531 17:22:53 server id 153443358 end_log_pos 33645 CRC32 0x4ea17869 GTID last_committed=125 sequence_number=126
SET @@SESSION.GTID_NEXT= 'e1028e43-4123-11e7-a3c2-005056aa17e6:198'/*!*/;
# at 33645
#170531 17:22:53 server id 153443358 end_log_pos 33717 CRC32 0x66820e00 Query thread_id=4 exec_time=0 error_code=0
SET TIMESTAMP=1496222573/*!*/;
BEGIN
/*!*/;
# at 33717
#170531 17:22:53 server id 153443358 end_log_pos 33770 CRC32 0x22ddf25e Table_map: `test`.`xcytest` mapped to number 222
# at 33770
#170531 17:22:53 server id 153443358 end_log_pos 33817 CRC32 0x61051ea0 Write_rows: table id 222 flags: STMT_END_F
BINLOG '
bYsuWRMeXCUJNQAAAOqDAAAAAN4AAAAAAAEABHRlc3QAB3hjeXRlc3QAAgMPAlgCAl7y3SI=
bYsuWR4eXCUJLwAAABmEAAAAAN4AAAAAAAEAAgAC//x9AAAABQBzZGZhc6AeBWE=
'/*!*/;
### INSERT INTO `test`.`xcytest`
### SET
### @1=125 /* INT meta=0 nullable=0 is_null=0 */
### @2='sdfas' /* VARSTRING(600) meta=600 nullable=1 is_null=0 */
# at 33817
#170531 17:22:53 server id 153443358 end_log_pos 33848 CRC32 0x630805b4 Xid = 303
COMMIT/*!*/;
每一个at xxxxx段，是一个event .
而函数Binlog_sender::send_events 就是发送binlog中的event事件的函数:
我们来解析一下这个函数：
函数入参：end_pos，当前读到的binlog文件的最末尾位置。
log_cache，记录是当前传送的日志的信息，包含已经传送的binlog日志的位置，以及binlog日志文件。
函数逻辑分析：
如果当前已发送的位置log_pos小于已获取到的文件的末尾位置end_pos.则表明还有binlog日志未发送，进入循环。
循环体内：
a. 首先调用函数read_event,获取一个事件event.
b. Log_event_type event_type= (Log_event_type)event_ptr[EVENT_TYPE_OFFSET];
该语句用来获取事件event的类型，然后进行类型检查
check_event_type(event_type, log_file, log_pos)，如果没有通过检查，直接返回1给上层函数。
c. log_pos= my_b_tell(log_cache); 更新log_pos位置，也就是将读binlog位置的游标前移到当前位置。
d. 然后调用send_packet() 函数进行binlog的发送。
原来， 不管当前还有多少binlog没有同步到从库，主库发送binlog的粒度依然是一个一个event的发送，发送之前，还需要检查event的类型。因为是小包发送，所以网络的流量并不大。
但需要说明一下出现这个现象的前提条件：我们测试环境中，当时数据库的写qps达到了50000以上，所以需要发送的event特别多，即使是异步，也导致单线程的dump线程来不及发送当前产生的日志。
当写的qps巨大的时候，确实存在来不及发送日志的情景。
2 总结
现在，再来回头看线上遇到的问题，“同步状态经常从半同步状态变成异步状态，然后又被及时复原到半同步状态”，原因是该数据库是一个分析系统，有时候会做批量的更新，以及批量的导入。同时，数据库设置的binlog格式为row模式，对于一个更新多行的事务，里面包含很多的event(一行是一个event), 所以发送这个事务的binlog耗时会比较长，无法在1秒钟内发送完成（半同步的timeout时间设置为1），所以半同步状态变成了异步。
标签：binlog,log,pos,主从,发送,mysql,日志,event,延迟 来源： https://blog.51cto.com/15057824/2648669
本站声明： 1. iCode9 技术分享网（下文简称本站）提供的所有内容，仅供技术学习、探讨和分享； 2. 关于本站的所有留言、评论、转载及引用，纯属内容发起人的个人观点，与本站观点和立场无关； 3. 关于本站的所有言论和文字，纯属内容发起人的个人观点，与本站观点和立场无关； 4. 本站文章均是网友提供，不完全保证技术分享内容的完整性、准确性、时效性、风险性和版权归属；如您发现该文章侵犯了您的权益，可联系我们第一时间进行删除； 5. 本站为非盈利性的个人网站，所有内容不会用来进行牟利，也不会利用任何形式的广告来间接获益，纯粹是为了广大技术爱好者提供技术内容和技术思想的分享性交流网站。