共计 2803 个字符,预计需要花费 8 分钟才能阅读完成。
之所以进行这块内容的研究,主要针对之前遇到的两个未解的疑惑:
a. 线上有个系统,半同步状态经常从半同步变成异步,然后又马上恢复为半同步,具体原因未明,虽然之前也猜得八九不离十,但还是未完全确定。
b. 前段时间因为有业务场景需求,做了跨机房异步复制测试。当 mysql 写 qps 非常高的时候,发现很多日志还没有来得及发送到从库,也就是 binlog 日志在主库的产生速度大于传送到从库的速度,这个速度差一直存在,因此当主库在持续高压力地产生 binlog 的时候,越来越多的 binlog 没有传送到从库,但当时的网络流量也才 18M/ S 左右(一主一从),从常规的知识认为,千兆的网络传送的速度可以达到 100M,而当前的主从之间的 binlog 传送速度只达到了 18M 左右,原因是什么?是网络问题?还是其他原因。
当主从复制关系建立之后,主库上有个 dump 线程,用来传送在主库产生的 binlog 日志的,而从库上的 io 线程,则用来接收由 dump 线程通过网络传送到从库的 binlog 日志,并负责将其写入 relay log 中去。这就是主从复制的机制,同时,由于是异步复制,传送过程不需要 ack 的确认。
疑问也正在此处——因为是异步传输,如果单纯地理解为 binlog 文件直接网络传送,这个速度应该很快才是,但实际情况: 在我们的测试环境中,binlog 日志的传送速度才 18M/s,小于日志产生的 22M/ s 左右的速度。为什么只有这个速度,而没有把网络带宽用满?原因是什么?
主从复制的结构中,主库上的 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 巨大的时候,确实存在来不及发送日志的情景。
现在,再来回头看线上遇到的问题,“同步状态经常从半同步状态变成异步状态,然后又被及时复原到半同步状态”,原因是该数据库是一个分析系统,有时候会做批量的更新,以及批量的导入。同时,数据库设置的 binlog 格式为 row 模式,对于一个更新多行的事务,里面包含很多的 event(一行是一个 event), 所以发送这个事务的 binlog 耗时会比较长,无法在 1 秒钟内发送完成(半同步的 timeout 时间设置为 1),所以半同步状态变成了异步。