造成的复制延迟原因(从binlog入手分析)

2019/04/10 10:10
阅读数 71

•大事务造成的延迟,其延迟不会从0开始增加,而是直接从主库执行了这个事务多长时间开始的,从库也要一样的执行时间执行这个事务,而且事务执行时间累加上去,非常合理。

比如主库执行这个事务花费的20秒,那么延迟就会从20开始,

从 log_event.cc 看到,这是因为 Query Event 中没有准确的执行时间

log_event.cc

入口:

int Query_log_event::do_apply_event(Relay_log_info const *rli,
const char *query_arg, size_t q_len_arg)

包括: sql_mode , 客户端字符集,自增环境设置,登陆的db,结果执行时间,ddl和dml执行时间
dml: 数据被写盘后的时间 thd->set_time(&(common_header->when)); , 一个事务对应一个Query_Event 
ddl: 实际语句执行时间 thd->set_time(&(common_header->when)); 整个语句执行后才写入执行时间

show slave status 入口:

rpl_slave.cc:

bool show_slave_status_send_data(THD *thd, Master_info *mi,
char* io_gtid_set_buffer,
char* sql_gtid_set_buffer)


if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
(!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))

 

检查SQL线程是否在中继日志的末尾
        检查应使用两个条件进行
        condition1:比较日志位置和
        condition2:比较文件名

获得 seconds_behind_master 时间
long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp) - mi->clock_diff_with_master);

系统时间 (long)(time(0)
主从之间系统时间差值 mi->clock_diff_with_master

1. 重点:
主从服务器的操作系统时间要一致,因为这两个是可变不稳定因素

dml语句和ddl语句的执行时间 mi->rli->last_master_timestamp

 

log_event.cc

Query_log_event::Query_log_event(const char* buf, uint event_len,
const Format_description_event
*description_event,
Log_event_type event_type)

dml(从begin开始) 和 ddl 执行时间
exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;

rpl_slave.cc 
等于各个Event header 的 timestamp , 事务都是 GTID_EVENT 和 XID_EVENT 提交时间
rli->last_master_timestamp= ev->common_header->when.tv_sec + (time_t) ev->exec_time;

 

(题外话: cnblogs可以随便给其他网站爬虫( https://www.colabug.com/2020/0203/6936599/  ) , 我都还没写完它就爬 , cnblogs 一点保护不了作者劳动成果

 

binlog_event.h
class Log_event_header
·timeval:固定4字节,是新纪元时间(1970年1月1日0时0分0秒)以来的秒数。这个时
间是命令发起的时间。如何定义命令发起呢?它是执行计划生成后开始实际执行语句的
时候。源码可以是在dispatch一command函数的开头设置的(thd->set-time())。言外
之意对于语法意义、权限橙查、优化器生成执行计划的时间都包括在里面。其次要注意
了这个时间在从库计算Seconds一Behind一Master的时候是一个重要的依据


·type_code:固定1字节,event事件的编码。每TEvent有自己的编码。
·unmasked_server_id:固定4字节。就是生成这个Event服务端的serverid。即便从库端开启了
log-slave-updates%,从库将主库的Event写到BinaryLog,这个serverid也是主库
的serveride如果这个Event再冫欠传到主库,那么需要跳过。源码可以在


Log-event::do-shalLskip函数中找到跳过逻辑如下“

·event Len:固定4字节,整个Event的长度。
·end_log_p:固定4字节,下一个Event的开始位置。
.flags:固定2字节,某些Event包含这个标示,比如Format-descriptionlog_event中
LOG_EVENT_BINLOG_IN_USE_F 标示当前Binary log是当前写入文件。

class Log_event_footer
·Event footer中的crc:固定4字节,这部分就是整个Event的一个crc校验码,用于标示Event的完整性

 


因为能力和篇幅有限,不可能介绍所有的Event,本系列值介绍一些常用的Evnet,下面是本系 列将会介绍到了 Event:
• QUERY_EVENT=2 :在语句模式下记录实际的语句,在行模式下不记录任何语句相关 的倍息,
但是DDL始终是记录的语句,本系列值考虑行模式。因此即便是行模式下的 DDL也会记录为语句。
• FORMAT_DESCRIPTION_EVENT= 15:说明Binary log的版本信息。总包含在每一个 Binary log的开头。
• XID_EVENT=16:当事务提交的时候记录这个Event其中携带了XID信息。
• TABLE_MAP_EVENT = 19: 包含了tablejd和具体表名的映射。
• WRITE_ROWS_EVENT = 30: INSERT语句生成的Event,包含插入的实际数据。是行 模式才有的。
• UPDATE_ROWS_EVENT = 31: UPDATE语句生成的Event,包含数据的前后印象数 据。是行模式才有的
• DELETE_ROWS_EVENT = 32: DELETE语句生成的Event,包含实际需要删除的数 据。是行模式才有的。
• GTID_LOG_EVENT = 33: 如果开启GTID模式的时候生成关于GTID的倍息,并且携带 last commit和seq number作为MTS并行回放的依据。
• ANONYMOUS_GTIDJ_OG_EVENT=34:在关闭GTID模式的时候生成,并且携带last commit和seq number作为MTS并行回放的依据#。
• PREVIOUS_GIlDS_LOG_EVENT二35:说明前面所有的Binary log包含的GIlD SET, relay log则代表10线程收到的GTID SET。

参考Log_event_type


一、FORMAT DESCRIPTION EVENT
1、FORMAT_DESCRIPTION_EVENT的作用
携带的数据都是固定的,
包含了binary log的版本信息、MySQL的版本信息、Event_header的长度、
以及每个Event type的固定部分的长度。

下面倌患将会保存在从库的内存中:
• 在从库的内存中保存主库的倍息,这个变星是Master_info.mi_description_event。
queue_event函数中case binary_log::FORMAT_DESCRIPTION_EVENT部分。

• 将从库的relay log的FORMAT_DESCRIPTION_EVENT记录为和主库相同,
即更新 RelayJogInfo.rlLdescription_event

log_event.cc:
int Format_description_log_event::do_apply_event(Relay_log_info const *rli) 函数中如下片段:

如果从站未请求该事件,即Master发送了当从站要求位置> 4时,
该事件将使rli-> group_master_log_pos前进。 
说Slave要位置1000,Format_desc事件的结尾是96。
然后在复制rli-> group_master_log_pos的开始将是0,
然后是96,然后跳到第一个真正询问的事件(即> 96/* Save the information describing this binlog */
const_cast<Relay_log_info *>(rli)->set_rli_description_event(this);

至少下面几个地方都会读取其中的倍息:
1.    每次SQL线程应用Event的时候会获取Event_header的长度和相应Even個定部分的长度。
2.    I0线程启动的时候检测版本,參考函数 get_master_version_and_clock 。
3.    将倌患写入到 relay log 的开头的FORMAT_DESCRIPTION_EVENT中。
4. 位置必须在#4

 

rpl_slave.cc:
static int get_master_version_and_clock(MYSQL* mysql, Master_info* mi)

从库针对不同版本不同处理 , mysql>=5.0 都能复制
switch (version_number)
{
case 0:
case 1:
case 2:
errmsg = "Master reported unrecognized MySQL version";
err_code= ER_SLAVE_FATAL_ERROR;
sprintf(err_buff, ER(err_code), errmsg);
break;
case 3:
mi->set_mi_description_event(new
Format_description_log_event(1, mysql->server_version));
break;
case 4:
mi->set_mi_description_event(new
Format_description_log_event(3, mysql->server_version));
break;
default:
/*
Master is MySQL >=5.0. Give a default Format_desc event, so that we can
take the early steps (like tests for "is this a 3.23 master") which we
have to take before we receive the real master's Format_desc which will
override this one. Note that the Format_desc we create below is garbage
(it has the format of the *slave*); it's only good to help know if the
master is 3.23, 4.0, etc.
*/
mi->set_mi_description_event(new
Format_description_log_event(4, mysql->server_version));
break;
}
}

 


将binlog event 写入 binlog cache

log_event.cc
bool Format_description_log_event::write(IO_CACHE* file)

if (post_header_len_size == Binary_log_event::LOG_EVENT_TYPES)
相同版本主从服务器复制

else if (post_header_len_size > Binary_log_event::LOG_EVENT_TYPES)
在新的Master和旧的Slave之间复制。但不会从内存复制,所以任何内存不足的读取。

else
在旧版本的主服务器和新版本的从服务器之间复制。
在这种情况下,它可能导致 Master 和 Slave 上发生不同的number_of_events。 当循环relay log时,
来自Master的FORMAT_DESCRIPTION_EVENT用于在Slave上创建FORMAT_DESCRIPTION_EVENT事件,
该事件将在此处写入。 在这种情况下可能最终会读取更多字节,
如post_header_len.size()
<Binary_log_event::LOG_EVENT_TYPES;。引起内存问题。

 

binlog_version
server_version
create_timestamp
headerjength
array of post-header

•固定部分,这部分是大小不变的。
1. binlog_version: 2字节 binary log的版本当前为‘4’。
2. server_version: 50字节,MySQL的版本,为字符串形式#
3. create_timestamp: 4字节,MySQL每次启动的时候的第一个binary log的 FORMAT_DESCRIPTION_EVENT会记录,其他情况为0,源码有如下解释:
4. headerjength: 1 字节,Event header的长度。当前为‘19’。
5. array of post-header:当前版本为39字节#这是一个数组用于保存每个Event类型的固 定部分的大小9

生成时机
这个Event作为binary log的第一个Event, _般都是在binary log切换的时候发生比如:
• flush binary 丨ogs命令。
• binary log自动切换。
• 重启MySQL实例

最后注意下在本Event的Event header中flags如果为 LOG_EVENT_BINLOGJN_USE_F标示 说明当前binary log没有关闭(比如本binary log为当前写入文件或者异常关闭MySQL实 例)^如果异常关闭MySQL实例会检测这个值决定是否做binary log recovery。

二、PREVIOUS GTIDS LOG EVENT
1、PREVIOUS_GTIDS_LDG_EVENT的作用
这个Event只包含可变部分。通常作为binary log的第二个Event,用于描述前面所有的binary log包含的GTID SET (包括已经删除的)。初始化GTID模块的时候也会扫描 binary log中的这个Event*在relay log同样包含这个Event,主要用于描述I/O线程接收过哪些 GTID,后面能看到MySQL实例初始化的时候可能会扫描relay log中的这个Event来确认 Retrieved_Gtid_Set 。

 

3、 主体格式

整个写入过程集中在Gtid_set::encode函数中,因为GTID SET中可能出现多个server_uuid并 且可能出现'gap',因此是可变的。在Gtid_set::encode函数中我们也可以清晰的看到它在循环 GTID SET中的每个server_uuid和每一个GTID SET Interval,如下:
• 可变部分,这部分大小可变
• number of sids: 8字节# 小端显示,本GITD SET有多少个server_uuid
• server_uuid: 16字节。GTID SET中的server_uuid
• n_intervals: 8字节。本server_uuid下GTID SET Interval的个数
• inter_start: 8字节。每个GTID SET Interval起始的gno
• inter_next: 8字节。每个GTID SET Interval结尾的下一个gno

注意:甶于一个GTIDSET可以包含多个server_uuid,因此第2到第5部分可能包含多个。
如果 还包含多个GTID SET Interval则第4和第5部分也可能多个。


4、 实例解析
下面是一个PREVIOUS_GTIDS_LOG_EVENT (mysqlbinlog —hexdump 输出>,这种情况 是我手动删除了 auto.cnf手动构造出来的:

  (cnblog格式能否优美一下)

• 02 00 00 00 00 00 00 00:包含2个server_uuid U小端显示就是2个。

• 24 98 54 63 a5 36 11 e8 a3 0c 52 54 00 81 38 e4:第一个server_uuid。
• 01 00 00 ◦0 00 00 00 00: njntervals表示本GTID SET Interval的个数。小端显示就 是1个
• 01 00 00 00 00 00 00 00: inter_start,第一个GTID SET Interva丨的起始的gno为1
• 08 00 00 00 00 00 00 00: inter_next,第一个GTID SET Interval结尾的下一个gno为8.
• 6c ea 48 f6 92 6c 11 e9 b1 cb 52 54 00 81 38 e4:第二个server_uuid
• 01 00 00 00 00 00 00 00: njntervals表示本GT丨D SET Interval的个数。小端显示就 是1个
• 01 00 00 00 00 00 00 00: inter_start,第一个GTID SET Interva丨的起始的gno为 1
• 05 00 00 00 00 00 00 00: inter_next,第一个GTID SET Interval结尾的下一个gno位

我们看到解析出来的:

• 24985463-a536-11e8-a30c-5254008138e4:1-7
• 6cea48f6-926c-11e9-b1cb-5254008138e4:1-4
可以看到它们是一致的,只是inter_next应该减去了 1,因为Event中记录的是GTID SET Interval结尾的下一个gno*


5、生成时机
生成时机一般也是进行binary log切换的时候作为第二个Event写入binary log


7、重点 Event

GTID_LOG_EVENT
因为GTID_LOG_EVENT和ANONYMOUS_GTID_LOG_EVENT格式一致,只是 携带的数据不一样而已,只解释GTID_LOG_EVENT即可
一、GTID LOG EVENT
(1) GTID_LOG_EVENT的作用
只需要知道GTID_LOG_EVENT 这个Event主要记录的部分有下面三个:

• GTID的详细倌息。
• 逻辑时钟详细倍息,即 last commit 和 seq number
• 是否为行模式,比如DDL语句就不是行模式的

显示开启事务的情况下GTID_LOG_EVENT和XID_EVENT Event header的 timestamp都是commit命令发起的时间,

当然如果没有显示开启事务那么timestamp还是命 令发起的时间。

log_event.cc

  

固定部分
• flags: 1字节。主要用于表示是否是行模式的,如果是则为0X00。不是则为0X01,注意 DDL都不是行模式的,而是语句模式
• server_uuid: 16字节。server_uuid參数去掉中间的16进制表示。
• gno: 8字节。小端显示。表示GTID的序号。
• ts type: 1字节•固定为02。
• last commit: 8字节。小端显示。
• seq number: 8字节。小端显示。
 

(4)简单解析
下面是一个的GTID_LOG_EVENT(mysqlbinlog—hexdump 输出):

 

#191218 21:08:49 server id 1 end_log_pos 417 CRC32 0xac5430b1
# Position Timestamp Type Master ID Size Master Pos Flags
# 160 e1 24 fa 5d 21 01 00 00 00 41 00 00 00 a1 01 00 00 00 00
# 173 00 12 cf ee 78 e5 80 11 e6 a7 90 00 ff 05 93 af |....x...........|
# 183 ce 02 00 00 00 00 00 00 00 02 01 00 00 00 00 00 |................|
# 193 00 00 02 00 00 00 00 00 00 00 b1 30 54 ac |...........0T.|
# GTID last_committed=1 sequence_number=2 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

mysql> show variables like '%uuid%';
+---------------+--------------------------------------+
| Variable_name | Value |
+---------------+--------------------------------------+
| server_uuid | 12cfee78-e580-11e6-a790-00ff0593afce |
+---------------+--------------------------------------+
1 row in set (0.00 sec)

• 02 00 00 00 00 00 00 00:这就是GTID的序号,小端显示就是0X02, 10进制的2
• 02: ts type
• 01 00 00 00 00 00 00 00:即last_committed=1 , 小端显示就是0X01
• 02 00 00 00 00 00 00 00:即sequence_nunnber=2 ,小端显示就是0X02

 

• 40 00 00 00 00 00 00 00:这就是GTID的序号,小端显示就是0X40, 10进制的64
• 02: ts type
• 01 00 00 00 00 00 00 00:即last_committed=1,小端显示就是0X01
• 02 00 00 00 00 00 00 00:即sequence_nunnber=2 ,小端显示就是0X02


(5) 生成时机
关于生成时机来讲GTID_LOG_EVENT的生成和写入binary log文件都是 order commit 的flush 阶段

(6) ANONYMOUS_GTID_LOG_EVENT
这是匿名GTID Event, 5.7如果不开启GTID则使用这种格式。它除了不生成GTID相关倍患外 和GTID_LOG_EVENT保持一致,即如下部分全部为0:
• server_uuid
• gno

(7) GTID三种模式
•自动生成GTID:主库一般是这种情况(AUTOMATIC_GROUP)
•指定GTID:从库或者使用GTID_NEXT—般就是这种情况(GTID_GROUP)
•匿名GTID:当然也就是不开启GTID了时候了(ANONYMOUS_GROUP)
源码的注释

rpl_gtid.h

/**
Specifies that the GTID has not been generated yet; it will be
generated on commit. It will depend on the GTID_MODE: if
GTID_MODE<=OFF_PERMISSIVE, then the transaction will be anonymous;
if GTID_MODE>=ON_PERMISSIVE, then the transaction will be assigned
a new GTID.

This is the default value: thd->variables.gtid_next has this state
when GTID_NEXT="AUTOMATIC".

It is important that AUTOMATIC_GROUP==0 so that the default value
for thd->variables->gtid_next.type is AUTOMATIC_GROUP.
*/
AUTOMATIC_GROUP= 0,
/**
Specifies that the transaction has been assigned a GTID (UUID:NUMBER).

thd->variables.gtid_next has this state when GTID_NEXT="UUID:NUMBER".

This is the state of GTID-transactions replicated to the slave.
*/
GTID_GROUP,
/**
Specifies that the transaction is anonymous, i.e., it does not
have a GTID and will never be assigned one.

thd->variables.gtid_next has this state when GTID_NEXT="ANONYMOUS".

This is the state of any transaction generated on a pre-GTID
server, or on a server with GTID_MODE==OFF.
*/
ANONYMOUS_GROUP,
/**
GTID_NEXT is set to this state after a transaction with
GTID_NEXT=='UUID:NUMBER' is committed.

This is used to protect against a special case of unsafe
non-transactional updates.

Background: Non-transactional updates are allowed as long as they
are sane. Non-transactional updates must be single-statement
transactions; they must not be mixed with transactional updates in
the same statement or in the same transaction. Since
non-transactional updates must be logged separately from
transactional updates, a single mixed statement would generate two
different transactions.

Problematic case: Consider a transaction, Tx1, that updates two
transactional tables on the master, t1 and t2. Then slave (s1) later
replays Tx1. However, t2 is a non-transactional table at s1. As such, s1
will report an error because it cannot split Tx1 into two different
transactions. Had no error been reported, then Tx1 would be split into Tx1
and Tx2, potentially causing severe harm in case some form of fail-over
procedure is later engaged by s1.

To detect this case on the slave and generate an appropriate error
message rather than causing an inconsistency in the GTID state, we
do as follows. When committing a transaction that has
GTID_NEXT==UUID:NUMBER, we set GTID_NEXT to UNDEFINED_GROUP. When
the next part of the transaction is being processed, an error is
generated, because it is not allowed to execute a transaction when
GTID_NEXT==UNDEFINED. In the normal case, the error is not
generated, because there will always be a Gtid_log_event after the
next transaction.
*/
UNDEFINED_GROUP,
/*
GTID_NEXT is set to this state by the slave applier thread when it
reads a Format_description_log_event that does not originate from
this server.

Background: when the slave applier thread reads a relay log that
comes from a pre-GTID master, it must preserve the transactions as
anonymous transactions, even if GTID_MODE>=ON_PERMISSIVE. This
may happen, e.g., if the relay log was received when master and
slave had GTID_MODE=OFF or when master and slave were old, and the
relay log is applied when slave has GTID_MODE>=ON_PERMISSIVE.

So the slave thread should set GTID_NEXT=ANONYMOUS for the next
transaction when it starts to process an old binary log. However,
there is no way for the slave to tell if the binary log is old,
until it sees the first transaction. If the first transaction
begins with a Gtid_log_event, we have the GTID there; if it begins
with query_log_event, row events, etc, then this is an old binary
log. So at the time the binary log begins, we just set
GTID_NEXT=NOT_YET_DETERMINED_GROUP. If it remains
NOT_YET_DETERMINED when the next transaction begins,
gtid_pre_statement_checks will automatically turn it into an
anonymous transaction. If a Gtid_log_event comes across before
the next transaction starts, then the Gtid_log_event will just set
GTID_NEXT='UUID:NUMBER' accordingly.
*/
NOT_YET_DETERMINED_GROUP
};

 

 

一、QUERY_EVENT
(1) QUERY_EVENT的作用
QUERY_EVENT不仅会记录一些语句运行的环境比如SQL_MODE,客户端字符集、自增环境 , 设置、当前登录数据库等,而且会记录执行时间。但对于行模式的DDL和DML记录的执行时间 会有所不同t如下:
• DML:执行时间记录的是第一条数据更改后的时间,而不是真正本条DML语句执行的时间(一个DML语句可能修改很多条数据),往往这个时间非常短,不能正确的表示DML 语句执行的时间 , 语句部分记录的是’BEGIN’
• DDL:执行时间是实际语句的执行时间,语句部分记录的是实际的语句。
执行时间是Seconds_Behind_Master计算的一个影晌因素,对于一个事务来讲只有一个这样的QUERY_EVENT。

 

 

 

格式部分(单位:bytes):

 

 

 

固定部分,这部分是大小不变的。

• slave_proxy_id:4字节,主库生成本Event的 thread id,它和show processlist中的id 对应,
• query_exec_time: 4字节,这就是执行时间了。但是对于行模式的DML语句来讲这个执 行时间并不准确,上面已经描述了原因。而对于DDL来讲还是比较准确的。
• db_len: 1字节,用于描述数据库名的长度0
• error_code: 2字节,执行语句的错误码。
• status_vars_len: 2字节,status variables部分的长度。

可変部分,这部分是可变的。
• status variables:这部分是一个环境参数的设置,其中包含了很多种格式。每种格式都 有自己的长度和数据域,因此可以轻松的读取到各种值,比如SQL_MODE,客户端字符 集、自增环堍、客户端排序字符集等,但是其过于复杂这里不做实际解析。
• db:当前登录的database名字,以0x00结尾。主库来源为thd->db。如果是语句模式从 库做过滤的时候会使用这个名字。下面是逻辑验证:
• query:这就是具体的语句9对于行模式的DML来讲就是‘BEGIN’,而对于DDL来讲就是 具体的语句。
如果我们打开Query_log_event::do_apply_event函数就会看到这个Event在从库应用的时候就 是设置各种环境比如客户端字符集、自增环境设置、当前登录数据库等,然后执行相应的语 句,而对于行模式的DML这里只会执行‘BEGIN、这里注意一个细节,其中包含一句:
这句代码会设置线程的命令执行时间为Event header中Timestamp的吋间,因此在从 库上执行now()函数时是可以得到正确的结果的。

 

statement_events.cpp:

从Slave读取来源:

Query_event::Query_event(const char* buf, unsigned int event_len,
const Format_description_event *description_event,
Log_event_type event_type)

 

......

// 读取 status variables

start= (Log_event_header::Byte*) (buf + post_header_len);
end= (const Log_event_header::Byte*) (start + status_vars_len);

// 读取 db

  db= (const char* )end;

 

一、QUERY-EVENT
(1) QUERY_EVENT的作用
QUERY_EVENT不仅会记录一些语句运行的环境比如SQL_MODE,客户端字符集、自增环境 设置、当前登录数据库等,而且会记录执行时间。但对于行模式的DDL和DML记录的执行时间 会有所不同t如下:
• DML:执行时间记录的是第一条数据更改后的时间,而不是真正本条DML语句执行的时 间(一个DML语句可能修改很多条数据),往往这个时间非常短,不能正确的表示DML 语句执行的时间 , 语句部分记录的是’BEGIN’
• DDL:执行时间是实际语句的执行时间,语句部分记录的是实际的语句。
执行时间是Seconds_Behind_Master计算的一个影晌因素,对于一个事务来讲只有一个这样的QUERY_EVENT。

 

 


如果我们打开 QueryLog_event::do_apply_event 函数就会看到这个Event在从库应用的时候就 是设罝各种环境比如客户端字符集、自增环境设罝、当前登录数据库等,然后执行相应的语 句,而对于行模式的DML这里只会执行‘BEGIN’。这里注意一个细节,其中包含一句:

log_event.cc

int Load_log_event::do_apply_event(NET* net, Relay_log_info const *rli,
bool use_rli_only_for_errors)

......

if (rpl_filter->db_ok(thd->db().str))
{
thd->set_time(&(common_header->when));

这句代码会设罝线程的命令执行时间为Event header中Timestamp的时间。因此当我们在从 库上执行now()函数时是可以得到正确的结果的

 

 

(4)实例解析
下面是一个行模式的DML的QUERY_EVENT (mysqlbinlog --hexdump 输出):

slave_proxy_id 4 bytes
query_exec_time 4 bytes
db_len 1 bytes
error_code 2 bytes
status_vars_len 2 bytes
status_variables 可变
db 可变
query 可变


固定部分,这部分是大小不变的。
• slave_proxy_id:4字节,主库生成本Event的thread丨d,它和show processlist中的id 对应,
• query_exec_time: 4字节,这就是执行时间了。但是对于行模式的DML语句来讲这个执 行时间并不准确,上面已经描述了原因。而对于DDL来讲还是比较准确的。
• db_len: 1字节,用于描述数据库名的长度0
• error_code: 2字节,执行语句的错误码。
• status_vars_len: 2字节,status variables部分的长度。

可変部分,这部分是可变的。
• status variables:这部分是一个环境参数的设置,其中包含了很多种格式。每种格式都 有自己的长度和数据域,因此可以轻松的读取到各种值,比如SQL_MODE,客户端字符 集、自增环堍、客户端排序字符集等,但是其过于复杂这里不做实际解析。
• db:当前登录的database名字,以0x00结尾。主库来源为thd->db。如果是语句模式从 库做过滤的时候会使用这个名字。下面是逻辑验证:

从读取来源:

statement_events.cpp
Query_event::Query_event(const char* buf, unsigned int event_len,
const Format_description_event *description_event,
Log_event_type event_type)

end= (const Log_event_header::Byte*) (start + status_vars_len);
db= (const char* )end;
// 这里将指针指向 Query_event header中的db-name

log_event.cc
int Query_log_event::do_apply_event(Relay_log_info const *rli,
const char *query_arg, size_t q_len_arg)

// 读取db-name
set_thd_db(thd, db, db_len);

 

log_event.cc 调用 rpl_filter.cc , rpl_filter.h

bool
Rpl_filter::db_ok_with_wild_table(const char *db)

 

• query:这就是具体的语句9对于行模式的DML来讲就是‘BEGIN’,而对于DDL来讲就是 具体的语句。
如果我们打开Query_log_event::do_apply_event函数就会看到这个Event在从库应用的时候就 是设置各种环境比如客户端字符集、自增环境设置、当前登录数据库等,然后执行相应的语 句,而对于行模式的DML这里只会执行‘BEGIN、这里注意一个细节,其中包含一句:
这句代码会设霣线程的命令执行时间为Event header中Timestamp的吋间,因此当我们在从 库上执行now()函数时是可以得到正确的结果的。


(4)实例解析
下面是一个行模式的DML的QUERY_EVENT (mysqlbinlog --hexdump 输出):

# at 417
#191218 21:08:49 server id 1 end_log_pos 490 CRC32 0x1b37cdc7
# Position Timestamp Type Master ID Size Master Pos Flags
# 1a1 e1 24 fa 5d 02 01 00 00 00 49 00 00 00 ea 01 00 00 08 00
# 1b4 03 00 00 00 00 00 00 00 05 00 00 1a 00 00 00 00 |................|
# 1c4 00 00 01 00 00 00 00 00 00 00 00 06 03 73 74 64 |.............std|
# 1d4 04 2d 00 2d 00 21 00 77 6f 72 6c 64 00 42 45 47 |.......world.BEG|
# 1e4 49 4e c7 cd 37 1b |IN..7.|
# Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1576674529/*!*/;
BEGIN

固定部分
• 03 00 00 00: thread id 3.
• 00 00 00 00:执行时间,对于行模式的DML来讲通常不准。
• 05:当前登录库名的长度。
• 00 00:错误码#
• 1a 00: status variables部分的长度16进制 '1a' 就是十进制26。

可变部分
• status variables:略。
• 77 6f 72 6c 64 00:当前登录库名world的ASCII编码,以0x00结尾
• 42 45 47 49 4e:语句‘BEGIN’的ASCII编码

中间有部分就是我们的status variables,这部分过于复杂我没有仔细研究,因此我就没做解析了

(5) 生成时机
•对于行模式的DML而言,生成时机是事务的第一个DML语句第一行需要修改的数据在 Innodb引擎层修改完成后。通常来讲一个事务对应了一个QUERY_EVENT。
•对于DDL而言,生成时机是在整个操作执行完成之后。

二、MAP_EVENT
(1) MAP_EVENT的作用
MAP_EVENT是行模式特有的,它主要作用是做table id和实际访问表的映射。
同时其中还包 含了一些表的定义,如:表所在库名、表名、字段类型、可变字段长度等。
这里的库名和 QUERY_EVENT的库名不一样,这个库名来自表的定义,
而QUERY_EVENT的库名来自于当 前登录的数据库即:thd->db。
固定部分,这部分是大小不变的。


table_id 6 bytes
Reserved 2 bytes
db len 可变
db name 可变
table len 可变
table name 可变
no of cols 可变
array of col types 可变
metadata len 可变
metadata block 可变
m_null_bits 可变


• table id: 6字节,这个table id和Innodb层的table id不一样,他分配的时机是第一次打 开表定义的时候。它不是固定的,重启Mysql实例或
者flush tables都会导致其改变。

sql_base.cc
TABLE_SHARE *get_table_share(THD *thd, TABLE_LIST *table_list,
const char *key, size_t key_length,
uint db_flags, int *error,
my_hash_value_type hash_value)

assign_new_table_id(share);
share->table_map_id= last_table_id++; // 递增table id
在LOCK_open的保护下分配一个新的表ID。 这样做不是创建新的互斥锁
并将其仅用于序列化对 静态变量, 在此处分配表ID。我们将其分配给
共享,然后将其插入到table_def_cache中确保没有表就无法从缓存中读取它
分配的ID。

 

 

因此它是可变的。
• Reserved: 2字节,保留以后使用。
可变部分,这部分大小是可变的《
• dblen:表所在的数据库名长度。
• db name:表所在的数据库名以0x00结尾。
• table丨en:表名的长度。
• table name:表名以0x00结尾》
• no of cols:表中字段数。
• array of col types:字段的类型数组。
• metadata len: metadata block的长度v
• metadata block:对于可变字段需要记录字段的长度,但对于像int这种数据类型就不需 要了。下面是varchar关于可变长度的输出,可以看到它占用2个字节:

field.cc
int Field_varstring::do_save_field_metadata(uchar *metadata_ptr)
{
DBUG_ASSERT(field_length <= 65535);
int2store((char*)metadata_ptr, field_length);
return 2;
}

 

如果感兴趣可以査看do_save_field_metadata这个函数。
• m_null_bits:字段是否可以为空的一个位图。下面是位图的获取方式。

现在将数据的大小设置为字段元数据数组的大小
加上1或3个字节(请参阅pack.c:net_store_length)以获取
字段元数据数组中的元素。

log_event.cc
if (m_field_metadata_size < 251)
m_data_size+= m_field_metadata_size + 1; 
else
m_data_size+= m_field_metadata_size + 3;

memset(m_null_bits, 0, num_null_bytes);
for (unsigned int i= 0 ; i < m_table->s->fields ; ++i)
if (m_table->field[i]->maybe_null())
m_null_bits[(i / 8)]+= 1 << (i % 8);

 


(4) 实例解析
执行如下语句:

mysql> use test;
Database changed
mysql> create table test(id int(11) not null auto_increment,
-> a int(11) default null,
-> b int(11) default null,
-> primary key(id),
-> key idxa (a)
-> ,
-> key idxb (b)
-> ) engine=innodb auto_increment=10 default charset=utf8mb4;
Query OK, 0 rows affected (0.02 sec)

mysql> insert into test values(100,100,100);
Query OK, 1 row affected (0.01 sec)

# at 634
#200206 23:27:49 server id 1 end_log_pos 683 CRC32 0xf235602e
# Position Timestamp Type Master ID Size Master Pos Flags
# 27a 75 30 3c 5e 13 01 00 00 00 31 00 00 00 ab 02 00 00 00 00
# 28d 65 01 00 00 00 00 01 00 04 74 65 73 74 00 04 74 |e........test..t|
# 29d 65 73 74 00 03 03 03 03 00 06 2e 60 35 f2 |est.........5.|
# Table_map: `test`.`test` mapped to number 357

这个‘Insert’语句的MAP_EVENT为:
• 65 01 00 00 00 00: table id为 16进制的0165,转换为 10进制为 357
• 01 00:保留。
• 04:表所在的数据库名长度为4
• 74 65 73 74 00: 'test'的ASCII表示,以0x00结尾
• 04:表名的长度为2。
• 65 73 74 00: 'test'的ASCII表示,以0x00结尾
• 03:表拥有3个字段
• 03 03 03:每个字段的类型都是03,实际上就是int这种类型了。具体可以参考 enum_field_types 这个枚举类型
• 00: metadata长度为0,没有可变字段
• 06:转换为2进制为110,表示第一个字段不可以为空,其他两个字段可以为空

(5) 生成时机
本Event只会在行模式下生成#生成时机是事务的每条DML语句條改的第一行数据在Innodb引 擎层修改完成后,QUERY_EVENT生成之后。
通常来讲每个语句的每个表(Table List)都会 包含这样一个MAP_EVENT。
前面我们说过了table_id是可变的,甚至会出现下面的情况。我们来构造这种情况,还是使用 上面的 test.test表:

set global autocommit = off;

Session1:
begin;
insert into test.test values(1,2,3);

Session2:
flush tables;

Session1:
insert into test.test values(4,5,6);
commit;

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#200207 21:18:24 server id 1 end_log_pos 123 CRC32 0x0a0e6713 Start: binlog v 4, server v 5.7.19-enterprise-commercial-advanced-log created 200207 21:18:24
# at 123
#200207 21:18:24 server id 1 end_log_pos 194 CRC32 0x7fe14b87 Previous-GTIDs
# 12cfee78-e580-11e6-a790-00ff0593afce:17-21
# at 194
#200207 21:18:49 server id 1 end_log_pos 259 CRC32 0x99027597 GTID last_committed=0 sequence_number=1 rbr_only=no
SET @@SESSION.GTID_NEXT= '12cfee78-e580-11e6-a790-00ff0593afce:22'/*!*/;
# at 259
#200207 21:18:49 server id 1 end_log_pos 338 CRC32 0xe188ca4b Query thread_id=4 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1581081529/*!*/;
SET @@session.pseudo_thread_id=4/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
flush tables
/*!*/;
# at 338
#200207 21:19:00 server id 1 end_log_pos 403 CRC32 0xa13e5263 GTID last_committed=1 sequence_number=2 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '12cfee78-e580-11e6-a790-00ff0593afce:23'/*!*/;
# at 403
#200207 21:18:46 server id 1 end_log_pos 475 CRC32 0x4284ad54 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1581081526/*!*/;
BEGIN
/*!*/;
# at 475
#200207 21:18:46 server id 1 end_log_pos 524 CRC32 0xb34f27f8 Table_map: `test`.`test` mapped to number 360
# at 524
#200207 21:18:46 server id 1 end_log_pos 572 CRC32 0x8e20673a Write_rows: table id 360 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=2 /* INT meta=0 nullable=1 is_null=0 */
### @3=3 /* INT meta=0 nullable=1 is_null=0 */
# at 572
#200207 21:18:58 server id 1 end_log_pos 621 CRC32 0xa4f321aa Table_map: `test`.`test` mapped to number 361
# at 621
#200207 21:18:58 server id 1 end_log_pos 669 CRC32 0x3108b1d9 Write_rows: table id 361 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
### @1=4 /* INT meta=0 nullable=0 is_null=0 */
### @2=5 /* INT meta=0 nullable=1 is_null=0 */
### @3=6 /* INT meta=0 nullable=1 is_null=0 */
# at 669
#200207 21:19:00 server id 1 end_log_pos 700 CRC32 0xc7a499f7 Xid = 21
COMMIT/*!*/;
# at 700
#200207 21:19:14 server id 1 end_log_pos 723 CRC32 0x0357cffb Stop
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;


一个事务内 相同的表不同的 table_id ,

# at 475
#200207 21:18:46 server id 1 end_log_pos 524 CRC32 0xb34f27f8 Table_map: `test`.`test` mapped to number 360

# at 572
#200207 21:18:58 server id 1 end_log_pos 621 CRC32 0xa4f321aa Table_map: `test`.`test` mapped to number 361

 

Seconds_Behind_Master作为判断主从同步的一个重要它的计算方法。
同 时讨论有哪些需要注意的地方。这里还会说明Seconds_Behind_Master为0并不一定代表没有 延迟的原因。


一、 Seconds_Behind_Master计算的方式
当每次发起‘show slave status’命令的时候都会进行一次Seconds_Behind_Master的计 算,
其计算的方式集中在函数show_slave_status_send_data中,下面是一段伪代码,非常清晰:

rpl_slave.cc
/*
The pseudo code to compute Seconds_Behind_Master:
if (SQL thread is running)
{
if (SQL thread processed all the available relay log)
{ // sql线呈已经 apply 完所有 I/O线程写入的Event
if (IO thread is running)
print 0;    // 显示延迟为0
else
print NULL;
}
else
compute Seconds_Behind_Master;
}
else
print NULL;
*/

正式代码如下,这里有一点需要注慂就是如何判断SQL线程应用完了所有的Event的,下面这部 分实际的代码:


bool show_slave_status_send_data(THD *thd, Master_info *mi,
char* io_gtid_set_buffer,
char* sql_gtid_set_buffer)
...
if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
(!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))
{
if (mi->slave_running == MYSQL_SLAVE_RUN_CONNECT)
protocol->store(0LL);
else
protocol->store_null();
}
else
{
long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
- mi->clock_diff_with_master);

条件“mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()”
就是通过 10 线程读取到主库binary log的位罝和SQL线程应用到的主库binary log位罝进行比较来进行判断。
如果主从之间的网络状态很糟糕的话,
从库的SQL线程的应用Event的速度可能比10线程 读取Event的速度更快。
那么就会出现一种情况,虽然SQL线程应用完了所有的Event,
并且 Seconds_Behind_Master也显示为0,但是并不代表没有延迟,
这个时候的延迟主要在于10线 程读取Event过慢。
这也是如果Seconds_Behind_Master为0不代表没有延迟的第一个原因。

 

二、 影晌 Seconds_Behind_Master 计算的因素
一般看到的正常Seconds_Behind_Master是怎么计薄出来的呢?实际上也很简单源 码如下:
分别解释一下这三个因素:
(1) (long)(time(0):取当前从库服务器的系统时间。

(2) mi->clock_diff_with_master 
这个值是从库服务器的系统时间和主库服务器的系统时间的差值。
实际上它只在10线程启动的时候进行一次性计算,
就是如果启动 I/O 线程后人为的修改从库服务器的时间,
那么Seconds_Behind_Master的计算必然出 现问题。更有可能出现负数,
如果出现负数延迟依然显示为0,如下:

 

if (mi->rli->slave_running)
{
/*
Check if SQL thread is at the end of relay log
Checking should be done using two conditions
condition1: compare the log positions and
condition2: compare the file names (to handle rotation case)
*/
if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
(!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))
{
if (mi->slave_running == MYSQL_SLAVE_RUN_CONNECT)
protocol->store(0LL);
else
protocol->store_null();
}
else
{
long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
- mi->clock_diff_with_master);
/*
Apparently on some systems time_diff can be <0. Here are possible
reasons related to MySQL:
- the master is itself a slave of another master whose time is ahead.
- somebody used an explicit SET TIMESTAMP on the master.
Possible reason related to granularity-to-second of time functions
(nothing to do with MySQL), which can explain a value of -1:
assume the master's and slave's time are perfectly synchronized, and
that at slave's connection time, when the master's timestamp is read,
it is at the very end of second 1, and (a very short time later) when
the slave's timestamp is read it is at the very beginning of second
2. Then the recorded value for master is 1 and the recorded value for
slave is 2. At SHOW SLAVE STATUS time, assume that the difference
between timestamp of slave and rli->last_master_timestamp is 0
(i.e. they are in the same second), then we get 0-(2-1)=-1 as a result.
This confuses users, so we don't go below 0: hence the max().

last_master_timestamp == 0 (an "impossible" timestamp 1970) is a
special marker to say "consider we have caught up".
*/
protocol->store((longlong)(mi->rli->last_master_timestamp ?
max(0L, time_diff) : 0));
}


// max(0L,time_diff) 如果time_diff为负数取0

因此主从服务器最好保证时钟同步。
这也是Seconds_Behind_Master显示0并不代表没有延迟 的第二个原因。

 

(3) mi->rli->last_master_timestamp
这个值的取值就比较复杂,因为DML和DDL下是不同的。
如果是DML在单SQL线程和MTS下 又不一样。分开分析。

• DML (单SQL线程)
这种情况下前面已经说过了,SQL线程每次执行Event的时候会获取Event的相关信息如下:

rpl_slave.cc

// event header 的timestamp

static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
{
DBUG_ENTER("exec_relay_log_event");

/*
We acquire this mutex since we need it for all operations except
event execution. But we will release it in places where we will
wait for something for example inside of next_event().
*/
mysql_mutex_lock(&rli->data_lock);

/*
UNTIL_SQL_AFTER_GTIDS, UNTIL_MASTER_POS and UNTIL_RELAY_POS require
special handling since we have to check whether the until_condition is
satisfied *before* the SQL threads goes on a wait inside next_event()
for the relay log to grow.
This is required in the following case: We have already applied the last
event in the waiting set, but the relay log ends after this event. Then it
is not enough to check the condition in next_event; we also have to check
it here, before going to sleep. Otherwise, if no updates were coming from
the master, we would sleep forever despite having reached the required
position.
*/
if ((rli->until_condition == Relay_log_info::UNTIL_SQL_AFTER_GTIDS ||
rli->until_condition == Relay_log_info::UNTIL_MASTER_POS ||
rli->until_condition == Relay_log_info::UNTIL_RELAY_POS ||
rli->until_condition == Relay_log_info::UNTIL_SQL_VIEW_ID) &&
rli->is_until_satisfied(thd, NULL))
{
rli->abort_slave= 1;
mysql_mutex_unlock(&rli->data_lock);
DBUG_RETURN(1);
}

Log_event *ev = next_event(rli), **ptr_ev;

DBUG_ASSERT(rli->info_thd==thd);

if (sql_slave_killed(thd,rli))
{
mysql_mutex_unlock(&rli->data_lock);
delete ev;
DBUG_RETURN(1);
}
if (ev)
{
enum enum_slave_apply_event_and_update_pos_retval exec_res;

ptr_ev= &ev;
/*
Even if we don't execute this event, we keep the master timestamp,
so that seconds behind master shows correct delta (there are events
that are not replayed, so we keep falling behind).

If it is an artificial event, or a relay log event (IO thread generated
event) or ev->when is set to 0, or a FD from master, or a heartbeat
event with server_id '0' then we don't update the last_master_timestamp.

In case of parallel execution last_master_timestamp is only updated when
a job is taken out of GAQ. Thus when last_master_timestamp is 0 (which
indicates that GAQ is empty, all slave workers are waiting for events from
the Coordinator), we need to initialize it with a timestamp from the first
event to be executed in parallel.
*/
if ((!rli->is_parallel_exec() || rli->last_master_timestamp == 0) &&
!(ev->is_artificial_event() || ev->is_relay_log_event() ||
(ev->common_header->when.tv_sec == 0) ||
ev->get_type_code() == binary_log::FORMAT_DESCRIPTION_EVENT ||
ev->server_id == 0))
{
rli->last_master_timestamp= ev->common_header->when.tv_sec +
(time_t) ev->exec_time;
DBUG_ASSERT(rli->last_master_timestamp >= 0);
}

// query event 才有的执行时间

 

实际上因为行格式的binary log (本系只讨论行格式),DML中QUERY_EVENT的ev->exec_time基本为0因此可以忽略,
因为QUERY_EVENT中的exec_time只记录第一条数据更 改消耗的时间,且一般看到的是‘BEGIN’,
所以 last_master_timestamp就基本等于各个Event中header的timestamp。
但是对于一个事务而 言 GTID_EVENT 和 XID_EVENT 都是提交时刻的时间,
而对于其他Event都是命令发起 时刻的时间(显示“begin commit”开启事务的情况)。
因 此如果一个长时间未提交的事务在SQL线程应用的时候可能观察到Seconds_Behind_Master 的瞬间跳动。

以一个DML语句为例,假设主库10分钟后才提交这个事务,
那么可能延迟计算如 下(T1为语句执行时间,T1+10分钟为事务提交的时间,
T2为从库系统时间-主和从库的时间差,
T2每次执查询Seconds_Behind_Master可变,因为从库系统时间可变):
这种情况就能看到突然延迟跳到很大然后一下恢复正常,比如例子中为10分钟。

 

• DML (MTS)
实际上rli->last_master_timestamp会取值为检 查点位罝事务XID_EVENT的timestamp,流程大概如下:
因此last_master_timestamp就是检查点位罝事务的XID_EVENT header中的timestamp。
如果不开启‘slave_preserve_commit_order’参数,那么就可能出现‘gap’,

例如大事务在从库apply很慢,小事务已经很快完成了apply,这个大事务形成gap导致主从数据不一致
检查点只能停留 在‘gap’之前的一个事务,可能后面的事务已经执行完成了。
这种情况下延迟并不是那么准确 但是误差也不大,
因为默认slave_checkpoint_period参数设罝为300毫秒。
关于‘gap’后面可以调高参数slave_checkpoint_period参数,
以此来 证明MTS延迟的计算是以检查点为准的。

 

 

Seconds_Behind_Master作为判断主从同步的一个重要它的计算方法。
同 时讨论有哪些需要注意的地方。这里还会说明Seconds_Behind_Master为0并不一定代表没有 延迟的原因。


一、 Seconds__Behind_Masteri十算的方式
当每次发起‘show slave status’命令的时候都会进行一次Seconds_Behind_Master的计 算,
其计算的方式集中在函数show_slave_status_send_data中,下面是一段伪代码,非常清晰:

rpl_slave.cc
/*
The pseudo code to compute Seconds_Behind_Master:
if (SQL thread is running)
{
if (SQL thread processed all the available relay log)
{ // sql线呈已经 apply 完所有 I/O线程写入的Event
if (IO thread is running)
print 0;    // 显示延迟为0
else
print NULL;
}
else
compute Seconds_Behind_Master;
}
else
print NULL;
*/

正式代码如下,这里有一点需要注慂就是如何判断SQL线程应用完了所有的Event的,下面我们可以看看这部 分实际的代码:


bool show_slave_status_send_data(THD *thd, Master_info *mi,
char* io_gtid_set_buffer,
char* sql_gtid_set_buffer)
...
if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
(!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))
{
if (mi->slave_running == MYSQL_SLAVE_RUN_CONNECT)
protocol->store(0LL);
else
protocol->store_null();
}
else
{
long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
- mi->clock_diff_with_master);

 

条件“mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()”
就是通过 10 线程读取到主库binary log的位罝和SQL线程应用到的主库binary log位罝进行比较来进行判断。
如果主从之间的网络状态很糟糕的话,
从库的SQL线程的应用Event的速度可能比10线程 读取Event的速度更快。
那么就会出现一种情况,虽然SQL线程应用完了所有的Event,
并且 Seconds_Behind_Master也显示为0,但是并不代表没有延迟,
这个时候的延迟主要在于10线 程读取Event过慢。
这也是如果Seconds_Behind_Master为0不代表没有延迟的第一个原因。

二、 影晌 Seconds_Behind_Master 计算的因素
那么我们一般看到的正常Seconds_Behind_Master是怎么计薄出来的呢?实际上也很简单源 码如下:
我们来分别解释一下这三个因素:
(1) (long)(time(0):
取当前从库服务器的系统时间。

(2) mi->clock_diff_with_master
这个值是从库服务器的系统时间和主库服务器的系统时间的差值。
实际上它只在10线程启动的时候进行一次性计算,
言外之意就是如果我 们启动 I/O 线程后人为的修改从库服务器的时间,
那么Seconds_Behind_Master的计算必然出 现问题。更有可能出现负数,
如果出现负数延迟依然显示为0,如下:


protocol->store((longlong)(mi->rli->last_master_timestamp ?
max(0L, time_diff) : 0));
}
}
// max(0L,time_diff) 如果time_diff为负数取0

因此主从服务器最好保证时钟同步。
这也是Seconds_Behind_Master显示0并不代表没有延迟 的第二个原因。

(3) mi->rli->last_master_timestamp
这个值的取值就比较复杂,因为DML和DDL下是不同的。
如果是DML在单SQL线程和MTS下 又不一样。因此我们分幵讨论。

• DML (单SQL线程)
这种情况下前面我们已经说过了,SQL线程每次执行Event的时候会获取Event的相关信息如 下:

rpl_slave.cc
static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
{
....
// event header 的timestamp
rli->last_master_timestamp= ev->common_header->when.tv_sec +
(time_t) ev->exec_time;

 

// query event 才有的执行时间

实际上因为行格式的binary log (本系只讨论行格式),DML中QUERY_EVENT的ev->exec_time基本为0因此可以忽略,
因为QUERY_EVENT中的exec_time只记录第一条数据更 改消耗的时间,且我们一般看到的是‘BEGIN’,
所以 last_master_timestamp就基本等于各个Event中header的timestamp。
但是对于一个事务而 言我们知道GTID_EVENT和XID_EVENT都是提交时刻的时间,
而对于其他Event都是命令发起 时刻的时间(显示“begin commit”开启事务的情况)。
因 此如果一个长时间未提交的事务在SQL线程应用的时候可能观察到Seconds_Behind_Master 的瞬间跳动。

我们以一个‘Delete’语句为例,假设我们主库10分钟后才提交这个事务,
那么可能延迟计算如 下(T1为语句执行时间,T1+10为事务提交的时间,
T2为从库系统时间-主从时间差,
T2每 次执查询Seconds_Behind_Master可变,因为从库系统时间可变):
这种情况我就能看到突然延迟跳到很大然后一下恢复正常,比如例子中为10分钟。

 

• DML (MTS)
实际上rli->last_master_timestamp会取值为 checkpoint 位罝事务XID_EVENT的timestamp,流程大概如下:

log_event.cc
Slave_worker *Log_event::get_slave_worker(Relay_log_info *rli)
{

....
1. 工作线程执行到事务XID_EVENT时,取XID_EVENT的timestamp
ptr_group->checkpoint_seqno= rli->checkpoint_seqno;
ptr_group->ts= common_header->when.tv_sec + (time_t) exec_time; // Seconds_behind_master related
...

 

2. 当进行 checkpoint 的时候设置变量ts , 调用函数 mts_checkpoint_routine

GAQ是什么?

https://dev.mysql.com/doc/dev/mysql-server/8.0.15/classSlave__committed__queue.html#details

 

bool mts_checkpoint_routine(Relay_log_info *rli, ulonglong period,
bool force, bool need_data_lock)

/*
Update the rli->last_master_timestamp for reporting correct Seconds_behind_master.

If GAQ is empty, set it to zero.
Else, update it with the timestamp of the first job of the Slave_job_queue
which was assigned in the Log_event::get_slave_worker() function.
*/
ts= rli->gaq->empty()
? 0
: reinterpret_cast<Slave_job_group*>(rli->gaq->head_queue())->ts;
rli->reset_notified_checkpoint(cnt, ts, need_data_lock, true);
/* e

3. 修改 last_master_timestamp 值
rpl_rli.cc
void Relay_log_info::reset_notified_checkpoint(ulong shift, time_t new_ts,
bool need_data_lock,
bool update_timestamp)
{

...

if (update_timestamp)
{
if (need_data_lock)
mysql_mutex_lock(&data_lock);
else
mysql_mutex_assert_owner(&data_lock);
last_master_timestamp= new_ts;
if (need_data_lock)
mysql_mutex_unlock(&data_lock);
}
}

 

因此last_master_timestamp就是检查点位罝事务的XID_EVENT header中的timestamp。
如 果不开启‘slave_preserve_commit_order’参数,那么就可能出现‘gap’,
检查点只能停留 在‘gap’之前的一个事务,可能后面的事务已经执行完成了。
这种情况下延迟并不是那么准确 但是误差也不大,
因为默认slave_checkpoint_period参数设罝为300毫秒。
关于‘gap’后面我们可以调高参数slave_checkpoint_period参数,
以此来 证明MTS延迟的计算是以检查点为准的。


• DDL
同样是上面 DML (单SQL线程) 的公式:

rpl_slave.cc
static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
{
....
// event header 的timestamp
rli->last_master_timestamp= ev->common_header->when.tv_sec +
(time_t) ev->exec_time;

// query event 才有的执行时间

实际上DML和DDL计 算延迟的方式区别就在于这里的exec_time是否参与运算。
DDL记录Binary log中QUERY_EVENT记录的是实际的语句,exec_time就会记录整个语句执行完成所消耗的时间

 


三、 Seconds_Behind_Masteri十算方式总结


 

四、 MTS中Seconds_Behind_Masteri十算误差的测试
证明slave_checkpoint_period( 默认 300ms) 在MTS中的Seconds_Behind_Master计算和检查点有关。
从库操作如下:

set slave_checkpoint_period = 60000;
stop slave;
start slave;

 

然后在主库做手动做几个事务。然后查看Executed_Gtid_Set如下:

insert * 3;

show master status \G

 

 检查主库和从库的Executed_Gtid_Set 发现这些事务早就已经在从库 做完了

 


用上面的公式来套的话就是mi->rli->last_master_timestamp甶于MTS没有做 检查点而一直不变化,
直到60秒后才做了一次检查点,mi->rli->last_master_timestamp信 息才得到了更新。
从库show slave status,会发现Seconds_Behind_Master—直增长到60, 下面是延迟到了 60的截图:

 

 

 下面是变为0的截图:

 

 

但是这种问题一般不需要担心,
因为默认情况下参数slave_checkpoint_period为300毫秒,检 查点非常频繁。

 

五、 手动修改从库系统时间,导致Seconds_Behind_Master为0
这里再来测试一下手动修改从库系统时间的情况。
只需要在主库做一个大操 作,
导致从库有延迟。已经做了一个大表的DDL,当前从库的延迟如下,
从图中可以 看到gno为31的DDL操作还没有执行完成,导致延迟,如下:

  

然后我们将从库系统时间改小,如下:

修改系统时间
# date
# date -s 01:00:00


然后再次查看延迟, Seconds_Behind_Master为0,但是gno为31的DDL操作还是 没有执行完成,如下:

 

从库数据的查找和参数slave_rows_search_algorithms


对于DML语句来讲其数据的更改将被放到对应的Event中。
比 如‘Delete’语句会将所有删除数据的before Image放到 DELETE_ROWS_EVENT 中,
从库只要 读取这些beforejmage进行数据查找,
然后调用相应的‘Delete’的操作就可以完成数据的删除 了。
下面从库是如何进行数据查找的。
假定参数binlog_row_image设罝为‘FULL’也就是默认值,
binlog_row_image设置minimal 在不修改非空唯一索引和主键时候的字段时候 binlog是不包含非空唯一索引和主键的字段

一、没有Primary Key 和 唯一索引有索引的案例
在开始之前我们先假定参数‘slave_rows_search_algorithms’为默认值,即:
• TABLE_SCAN,INDEX_SCAN
因为这个参数会直接影响到对索引的利用方式。
以‘Delete’操作为例,实际上对于索引的选择‘Update’操作也是一样的,
因为都是通 过before Image去查找数据。我测试的表结构、数据和操作如下:

mysql>
create Table: CREATE TABLE 'aaa' (
'a' int(ll) DEFAULT NULL,
'b' int(ll) DEFAULT NULL,
'c' int(ll) DEFAULT NULL,
KEY 'a、 (、a、)
)ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set C0.00 sec)

mysql> delete from aaa where a=1;
Query OK, 3 rows affected (6.24 sec)

对于这样一个‘Delete’和'Update'语句来讲主库会利用到索引KEY a ,
删除的三条数据我们实际上只需 要一次索引的定位,
然后顺序扫描接下来的数据进 行删除就可以了。大概的流程和代码如下:

在没有唯一索引和Primary Key循环:
索引定位(申请 latch(空闲块和读取IO带宽优先) , B树的非叶子级别上使用修改的搜索模式 ,B树叶子中使用原始的搜索模式 ) -> 回表 -> 删除/修改该行 -> 访问下一行 -> 回表 -> 删除/修改该行

索引定位

btr0cur.cc
void
btr_cur_search_to_nth_level(
/*========================*/
dict_index_t*    index,    /*!< in: index */

 

 

这条数据删除/修改数据的 before_Image 将会记录到一个DELETE/UPDATE_ROWS_EVENT中。
从库 优先使用主键和唯一键,评估使用哪个索引,
在Event中的每条数据需要进行索引定位数据,
在非唯一索引情况第一次返回的第一行数据不删除数据,
继续扫描下一行

如下代码:

log_event.cc
int Rows_log_event::do_index_scan_and_update(Relay_log_info const *rli)
...
while (record_compare(m_table, &m_cols))
{
while((error= next_record_scan(false)))
{
/* We just skip records that has already been deleted */
if (error == HA_ERR_RECORD_DELETED)
continue;
DBUG_PRINT("info",("no record matching the given row found"));
goto end;
}
}

 

在没有主键和唯一键时候从库I/O的消耗代价是比主库更高的,
因此依旧使用的是索引KEY a ,
流程如下:

索引定位(申请 latch(空闲块和读取IO带宽优先) , B树的非叶子级别上使用修改的搜索模式 ,B树叶子中使用原始的搜索模式 ) -> 回表 -> 删除/修改该行 -> 访问下一行 -> 回表 -> 删除/修改该行


在从库增加一个主键,
那么在从库进行应用的时候流程如下:

循环:
主键定位 -> 删除本行

log_event.cc
int Rows_log_event::do_index_scan_and_update(Relay_log_info const *rli)

...

if (m_key_info->flags & HA_NOSAME || m_key_index == m_table->s->primary_key)
{
/* Unique does not have non nullable part */
if (!(m_key_info->flags & (HA_NULL_PART_KEY)))
goto end; // record found
else
{
/*
Unique has nullable part. We need to check if there is any field in the
BI image that is null and part of UNNI.
*/
bool null_found= FALSE;
for (uint i=0; i < m_key_info->user_defined_key_parts && !null_found; i++)
{
uint fieldnr= m_key_info->key_part[i].fieldnr - 1;
Field **f= m_table->field+fieldnr;
null_found= (*f)->is_null();
}

if (!null_found)
goto end; // record found

/* else fall through to index scan */
}
}

 


主库‘Delete/Update’操作和从库‘Delete/Update’操作主要的区别在于:
• 从库每条数据都需要索引定位查找数据。
• 从库在非唯一索引情况下查找第一条数据并不立刻删除/修改数据,而继续进行索引定位和查找。


对于主库来只需要一次数据定位查找即可,
接下来访问下一条数据就可以了。
删除/修改操作来讲并没有区别。
合理的使用主键和睢一键可以将上面提到的两点影晌延迟性能降低。
在从库延迟的时候,
没有合理的使用主键和唯一键是非常重要的原因。
最后如果表上一个索引都没有,情况变得更加严重,简单的图如下:

循环:
全表扫描 -> 删除本行

每一行数据的更改都需要进行全表扫描,
性能问题非常严重。
这种情况使用 slave_rows_search_algorithms 的HASH_SCAN代替TABLE_SCAN 在特定情况下也许可以提高性能,


二、确认查找数据的方式
slave_rows_search_algorithms 参数主要用于确认如何 查找数据。
其取值可以是下面几个组合(来自官方文档),源码中体现为一个位图:

• TABLE_SCAN,INDEX__SCAN (默认值)
• INDEX_SCAN,HASH_SCAN
• TABLE_SCAN,HASH_SCAN
• TABLE_SCANJNDEX_SCAN,HASH_SCAN

在源码中有如下的说明,当然官方文档也有类似的说明:

log_event.cc
int
Rows_log_event::row_operations_scan_and_key_setup()
....

 

根据 ROW_LOOKUP_HASH_SCAN , ROW_LOOKUP_INDEX_SCAN ,ROW_LOOKUP_TABLE_SCAN 调用

log_event.cc
void
Rows_log_event::decide_row_lookup_algorithm_and_key()
...

/*
Decision table:
- I --> Index scan / search
- T --> Table scan
- Hi --> Hash over index
- Ht --> Hash over the entire table

|--------------+-----------+------+------+------|
| Index\Option | I , T , H | I, T | I, H | T, H |
|--------------+-----------+------+------+------|
| PK / UK | I | I | I | Hi |
| K | Hi | I | Hi | Hi |
| No Index | Ht | T | Ht | Ht |
|--------------+-----------+------+------+------|

*/

 

 

源码中会有三种数据查找的方式,分别是:

• R0W_L00KUP_INDEX_SCAN
对应函数接口 :log_event.cc Rows_Log_event::do_index_scan_and_update

• R0W_L00KUP_HASH_SCAN
对应函数接口 : log_event.cc Rows_Log_event::do_hash_scan_and_update 包含:
(1) Hi --> Hash over index
(2) Ht --> Hash over the entire table
• R0W_L00KUP_TABLE_SCAN


对应函数接口 :

log_event.cc
int Rows_log_event::do_apply_event(Relay_log_info const *rli) 在源码中如下:

...
if ((m_rows_lookup_algorithm != ROW_LOOKUP_NOT_NEEDED) &&
!is_any_column_signaled_for_table(table, &m_cols))
{
error= HA_ERR_END_OF_FILE;
goto AFTER_MAIN_EXEC_ROW_LOOP;
}
switch (m_rows_lookup_algorithm)
{
case ROW_LOOKUP_HASH_SCAN:
do_apply_row_ptr= &Rows_log_event::do_hash_scan_and_update;
break;

case ROW_LOOKUP_INDEX_SCAN:
do_apply_row_ptr= &Rows_log_event::do_index_scan_and_update;
break;

case ROW_LOOKUP_TABLE_SCAN:
do_apply_row_ptr= &Rows_log_event::do_table_scan_and_update;
break;

case ROW_LOOKUP_NOT_NEEDED:
DBUG_ASSERT(get_general_type_code() == binary_log::WRITE_ROWS_EVENT);

/* No need to scan for rows, just apply it */
do_apply_row_ptr= &Rows_log_event::do_apply_row;
break;

default:
DBUG_ASSERT(0);
error= 1;
goto AFTER_MAIN_EXEC_ROW_LOOP;
break;
}

 


slave_rows_search_algorithms 参数不能决定使用哪个索引。
下面这个图就是决定的过程,可以参考函数 log_event.cc :  void Rows_log_event::decide_row_lookup_algorithm_and_key()

 

 

 

 

ROW_LOOKUP_HASH_SCAN方式的数据查找
总的来讲这种方式和 R0W_L00KUPJNDEX_SCAN 和 ROW_LOOKUP_TABLE_SCAN 都不 同,
它是通过表中的数据和Event中的数据进行比对,
而不是通过Event中的数据和表中的数据 进行比对。


将参数‘slave_rows_search_algorithms’设罝为叫 INDEX_SCAN,HASH_SCAN 且表上没有主键和唯一键的话,
把数据查找的方式设罝为 ROW_LOOKUP_HASH_SCAN。


在ROW_LOOKUP_HASH_SCAN 两种数据查找的方式:
• Hi ——> Hash over index
• Ht 一-> Hash over the entire table

判断 slave_rows_search_algorithms 使用方式
log_event.cc void Rows_log_event::decide_row_lookup_algorithm_and_key()
....
TABLE_OR_INDEX_HASH_SCAN:
....

1. 有索引情况下: 将binlog DELETE/UPDATE Event使用 Hi方式 将每一行数据 HASH 存入到 set结构中( log_event.cc , Rows_log_event::do_hash_row ),
然后对set进行索引定位扫描,每行数据查询 对 set结构中的数据 进行比对。重复数据越少,索引定位查找越多;重复数据越多,set元素减少,减少索引查找定位开销。

2. 没有索引情况下: 将binlog DELETE/UPDATE Event使用Ht 方式全表扫描,
一个Event最大8K,使用Ht会进行每个Event进行一次全表扫描(原来是每行数据 进行一次算表扫描)

考虑另外一种情况,如果每条delete/update语句一次只删除一行数据而不是delete/update—条语句大量的数据,
这种情况每个DELETE/UPDATE_ROWS_EVENT只有一条数据存在,
那么使用 ROW_LOOKUP_HASH_SCAN方式并不会提高性能,
因为这条数据还是需要进行一次全表扫 描或者索引定位才能查找到数据,
和默认TABLE_SCAN方式没什么区别。

 

整个过程参考如下接口:
• Rows_log_event::do_apply_event: 判断Hash Scan, Index Scan, Table Scan 入口
• Rows_Log_event::do_hash_scan_and_update: 总接口,调用下面两个接口。
• Rows_Log_event::do_hash_row: 将数据加入到hash结构,如果有索引还需要维护集合(set)
• Rows_log_event::do_scan_and_update: 查找并且进行删除操作,会调用 Rows_Log_event::next_record_scan 进行数据查找。
• Rows_Log_event::next_record_scan: 具体的查找方式实现了Hi --> Hash over index 和Ht --> Hash over the entire table的查找方式

 

还是用Delete的列子,删除了三条数据,
因此DELETE_ROW_EVENT中包含了 三条数据。
假设参数 slave_rows_search_algorithms 设置为 INDEX_SCAN,HASH_SCAN。
表中没有主键和唯一键,因此会最终使用 ROW_LOOKUP_HASH_SCAN进行数据查找。
但是因为有一个索引key a,因此会使用到 Hi—> Hash over index。为了更好的描述Hi和Ht两种方式,
假定另一种情况是表上一 个索引都没有,
将两种方式放到一个图中方便大家发现不同点,
如下图 :

 

 


总结
主库没有Primary Key如果在从库建立一个Primary Key能降低延迟吗?
肯定的,因为从库会根据Event中的行数据进行使用索引的选择。

• slave_rows_search_algorithms參数设罝了 HASH_SCAN并不一定会提高性能,只有满 足如下两个条件才会提高性能:
(1) (表中没有任何索引)或者(有索引且一个事务中的update/delete的数据关键字重复值较 多)。
(2) —个update/delete语句删除了大星的数据,
形成了很多个8K左右的 UPDATE_ROW_EVENT/DELETE_ROW_EVENT。
update/delete语句只修改少量的数 据(比如每个语句修改一行数据)并不能提高性能。

•从库索引的利用是自行判断的,顺序为主键-> 唯一键-> 普通索引。
•如果slave_rows_search_algorithms参数没有设罝HASH_SCAN,
并且没有主键/睢一键 那么性能将会急剧下降造成延迟。
如果连索引都没有那么这个情况更加严重,
因为更改 的每一行数据都会引发一次全表扫描。

 

因为 mi->clock__diff_with_master 只会在I0线程启动的时候进行 初始化,

如果手动改小从库服务器系统的时间,那么公式中的(long)(time(0))将变小,
如果整 个计算结果为负数那么Seconds_Behind_Master将显示为0。
因此我们需要保证主从服务器的 系统时间同步才行。

 

有了上面的分析我们应该清楚的知道在GTID AUTCLPOSITION MODE模式下,
应该通过 比较主库和从库的Executed_Gtld_Set来确保没有主从延迟,
因为比较 Seconds_Behind_Master是否为0并不一定靠谱。

 

从库的SQL线程(MTS协调线程)和参数 sql_slave_skip_counter

总的说来SQL线程有以下三个主要功能:
1. 读取relay log中的Event。
2. 应用这些读取到的Event,将修改作用于从库。
3. 如果是MTS通常情况下则不会应用Event,SQL线程会蜕变为协调线程,分发Event给工 作线程。


一、流程图

 


二、重要步骤说明
1、如果是MTS需要启动工作线程
每次重新启动SQL线程(MTS协调线程)的时候 slave_parallel_workers 参数 才会生效。


2、检查relay_log_info参数
在GTID AUTO_POSITION MODE模式下 和POSITION MODE模式下这个参数设罝非常重要参数 relay_log_info = TABLE ,
启动成功的关键就是slave_relay_log_info信息的正确性

如果没有设置为TABLE, MySQL就会出现Warning:
Slave SQL for channel If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0


3、 状态reading event from the relay log
开始读取Event的时候会进入状态:‘reading event from the relay log’。

4、 在MTS模式下判定是否需要进行MTS检查点
每读取一个Event都会去判断是否需要进行MTS的检查点,其条件有两个:
• MTS的检查点超过参数 slave_checkpoint_period 的设置
• GAQ队列已满

 

 


源码中如下:
是否超过检査点周期

rpl_slave.cc

处理rli-> gaq以找出存储在集中恢复表中的 lwm 位置。
bool mts_checkpoint_routine(Relay_log_info *rli, ulonglong period,
bool force, bool need_data_lock)

set_timespec_nsec(&curr_clock, 0);
ulonglong diff= diff_timespec(&curr_clock, &rli->last_clock);
if (!force && diff < period)
{
/*
We do not need to execute the checkpoint now because
the time elapsed is not enough.
*/
DBUG_RETURN(FALSE);
}

 

 

rpl_slave.cc
从中继日志中读取下一个事件。应该从从SQL线程中调用。
static Log_event* next_event(Relay_log_info* rli)

是否已经GAQ队列已经满了
//如果达到了 GAQ的大小设贸为force强制checkpoint
bool force= (rli->checkpoint_seqno > (rli->checkpoint_group - 1));

 

5、判断是否需要切换和清理relay log
事务是连续性,即使relay log 和binary log 当前满了也不能切换.
当recovery_relay_log = 0时候,可以打破事务连续性这个硬性条件
例如在GTID AUTO_POSITION MODE模式同时从库异常重启情况下relay log会产生partial transaction,
并且启动后恢复时候会造成额外回滚操作。
在POSITION MODE模式下继续发送事务余下部分的Event到当前relay log

源码注释如下,‘in a group’就代表在一个事务中:

/* 
If we have reached the limit of the relay space and we
are going to sleep, waiting for more events:

1. If outside a group, SQL thread asks the IO thread 
to force a rotation so that the SQL thread purges 
logs next time it processes an event (thus space is
freed).

2. If in a group, SQL thread asks the IO thread to 
ignore the limit and queues yet one more event 
so that the SQL thread finishes the group and 
is are able to rotate and purge sometime soon.
*/


rpl_slave.cc
relay_log_purge=ON, 非当前relay log读取完了的Event会进入清理流程。

if (relay_log_purge)    //做relay log的清理
{

if (rli->relay_log.purge_first_log
(rli,
rli->get_group_relay_log_pos() == rli->get_event_relay_log_pos()
&& !strcmp(rli->get_group_relay_log_name(),rli->get_event_relay_log_name())))
//做relay log的清理
{
errmsg = "Error purging processed logs";
goto err;
}
DBUG_PRINT("info", ("next_event group master %s %lu group relay %s %lu event %s %lu\n",
rli->get_group_master_log_name(),
(ulong) rli->get_group_master_log_pos(),
rli->get_group_relay_log_name(),
(ulong) rli->get_group_relay_log_pos(),
rli->get_event_relay_log_name(),
(ulong) rli->get_event_relay_log_pos()));
}
else
{
// 错误时候,锁定relay log
if (rli->relay_log.find_next_log(&rli->linfo, !hot_log))
{
errmsg = "error switching to the next log";
goto err;
}
rli->set_event_relay_log_pos(BIN_LOG_HEADER_SIZE);
rli->set_event_relay_log_name(rli->linfo.log_file_name);

rli->flush_info();
}

 

 

如果是读取完的是当前relay log,则不能进行清理,
会等待10线程的唤醒,
如果是MTS等待唤醒期间还需要进行MTS的检查点。


6、获取last_master_timestamp
在单SQL线程下计算Seconds_Behind_Master其中最重要的因素就来 自这里。
但是对于MTS而言,last_master_timestamp来自检查点指向 事务的XID_Event的时间,
因此MTS计算Seconds_Behind_Master的方法是不同。源码如 下:

rpl_slave.cc
static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
{
......
if ((!rli->is_parallel_exec() || rli->last_master_timestamp == 0) &&    //event header 的timestamp
!(ev->is_artificial_event() || ev->is_relay_log_event() ||
(ev->common_header->when.tv_sec == 0) ||    //query event才有的执行时间
ev->get_type_code() == binary_log::FORMAT_DESCRIPTION_EVENT ||
ev->server_id == 0))
{
rli->last_master_timestamp= ev->common_header->when.tv_sec +
(time_t) ev->exec_time;
//但是对于MTS来讲应该注意是最后一个XID EVENT的时间不是这里设置的,
//在 mts_checkpoint_routine 里面
DBUG_ASSERT(rli->last_master_timestamp >= 0);
}

......

 

注意到其中一个重要条件就是非MTS环境下,即!rli->is_parallel_exec()条件需要满足。


7、进行 partial transaction的恢复
下面两种情况可能出现这种情况:
• GTID AUTCLPOSITION MODE模式下如果 I/O 线程出现重连,DUMP线程会根据GTID SET进行重新定位,重发部分已经发送过的Event。
• GTID AUTCLPOSITION MODE模式下如果从库异常重启,并且recovery_relay_log=0 的情况下,
DUMP线程会根据GTID进行重新定位,重发部分已经发送过的Event。


这两种情况下甶于一个事务可能包含部分重暨的Event,就涉及到回滚操作。
对于MTS来讲是 由协调线程进行回滚,也就是这里。如果是非MTS环境下则在GTID Event应用的时候进行回 滚。


8、sql_slave_skip_counter參数
注意在GITD环境下不能使用sql_slave_skip_counter跳过Event
sql_slave_skip_counter参数的基本计数单位是Event,
但是如果最后一个Event正处于事务中 的时候,
整个事务也会被跳过。
源码:

log_event.cc
Log_event::enum_skip_reason
Log_event::do_shall_skip(Relay_log_info *rli)
{
DBUG_PRINT("info", ("ev->server_id=%lu, ::server_id=%lu,"
" rli->replicate_same_server_id=%d,"
" rli->slave_skip_counter=%d",
(ulong) server_id, (ulong) ::server_id,
rli->replicate_same_server_id,
rli->slave_skip_counter));
if ((server_id == ::server_id && !rli->replicate_same_server_id) ||
(rli->slave_skip_counter == 1 && rli->is_in_group()))
return EVENT_SKIP_IGNORE;
else if (rli->slave_skip_counter > 0)
return EVENT_SKIP_COUNT;
else
return EVENT_SKIP_NOT;
}

 

 

9、MTS进行分发,单SQL线程进行应用Event处理:
• MTS进行Event分发给工作线程进行Event的apply。
• 单SQL线程进行Event的应用。

 

三、各个Event大概做了什么
最终从库就开始应用Event 了,
开启GTID的情况下一个简单的‘Delete’语句生成的Event为例,Event包含:

Event:
1. GTID_EVENT
2. QUERY_EVENT
3. MAP_EVENT
4. DELETE_EVENT
5. XID_EVENT

1. GTID_EVENT
• 接口 log_event.cc int Gtid_log_event::do_apply_event(Relay_log_info const *rli)
• 单SQL线程下回滚partial transaction
• 设置事务的GTID 参考 set_gtid_next 函数。

2. QUERY_EVENT
參接□ int Query_log_event::do_apply_event(Relay_log_info const *rli)
• 设置线程的执行环境,比如SQL_MODE,客户端字符集、自增环境、客户端排序字符集、当前登录的数据库名等。
• 执行相应的语句。对于ROW模式的DML语句是‘BEGIN’,DDL而言就是执行实际的语句了。‘BEGIN’语句只是在MySQL层做了一个标记,如下:

lib_sql.cc
void *create_embedded_thd(int client_flag)
......
if (thd->variables.max_join_size == HA_POS_ERROR)
thd->variables.option_bits |= OPTION_BIG_SELECTS;

 

语句进入提交流程后会判断这个标记如下:

sql_class.h
inline bool in_multi_stmt_transaction_mode() const
{
return variables.option_bits & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN);
}

 


如果设罝了‘BEGIN’标记则不会进入order commit流程。


3. MAP_EVENT
• 接口 log_event.cc int Table_map_log_event::do_apply_event(Relay_log_info const *rli)
• 设置表的相关的属性,比如数据库名、表名、字段数量、字段类型、可变字段的长度等。
• 设置table id。


4. DELETE_EVENT
• 接口 log_event.cc int Rows_log_event::do_apply_event(Relay_log_info const *rli)
• 检查本事务是否GTID,是则需要跳过。这个判断过程位于函数 rpl_gtid_execution.cc static inline bool is_already_logged_transaction(const THD *thd)
• 打开表获取MDL锁。
• 设置table id和表的映射
• 开启读写事务。
• Innodb行锁。
• 对每行数据进行删除/修改操作。

可以看到对于从库来讲同样需要开启读写事务上锁等操作,
如果从库有相应 的DML操作,
SQL线程(MTS工作线程)也可能因为不能获得锁而堵塞。

5.XID_EVENT
• 接口log_event.cc int Xid_apply_log_event::do_apply_event(Relay_log_info const *rli) (单SQL线程)或者 int Xid_apply_log_event::do_apply_event_worker(Slave_worker *w) (MTS)
• 更新内存位点信息。
• 单SQL线程更新slave_relay_log_info表中的相关信息,MTS更新slave_worker_info表 中的相关信息。 rpl_info_table.cc int Rpl_info_table::do_flush_info(const bool force)为相应的更新接口。
• 进行提交操作。

 

binlog_group_commit_sync_delay 造成延迟

binlog.cc

int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit)

....

// 在sync_binlog= 1 才有这个延迟

if (!flush_error && (sync_counter + 1 >= get_sync_period()))
stage_manager.wait_count_or_timeout(opt_binlog_group_commit_sync_no_delay_count,
opt_binlog_group_commit_sync_delay,
Stage_manager::SYNC_STAGE);

 ...

void Stage_manager::wait_count_or_timeout(ulong count, long usec, StageID stage)
{
long to_wait=
DBUG_EVALUATE_IF("bgc_set_infinite_delay", LONG_MAX, usec);
/*
For testing purposes while waiting for inifinity
to arrive, we keep checking the queue size at regular,
small intervals. Otherwise, waiting 0.1 * infinite
is too long.
*/
long delta=
DBUG_EVALUATE_IF("bgc_set_infinite_delay", 100000,
max<long>(1, (to_wait * 0.1)));      // binlog_group_commit_sync_delay*0.1 和 1之间 , 1/1000000 秒 , 这参数随着增大下面循环消耗越多

while (to_wait > 0 && (count == 0 || static_cast<ulong>(m_queue[stage].get_size()) < count))    // binlog_group_commit_sync_delay时间消耗完
{
#ifndef DBUG_OFF
if (current_thd)
DEBUG_SYNC(current_thd, "bgc_wait_count_or_timeout");
#endif
my_sleep(delta);
to_wait -= delta;
}
}

 

总结出event 的offset 关系:

在没有mysql lib情况下 offset + 1:
event_time: EVENT_TIMESTAMP = 4
event_type: EVENT_TYPE_OFFSET = 5 - EVENT_TIMESTAMP

// 向前走
EVENT_LEN_OFFSET = 13 - EVENT_TYPE_OFFSET = 5 , SEEK_CUR

event_next: LOG_POS_OFFSET = 17 - EVENT_LEN_OFFSET = 13

event_size = event_next - event_pos = ( fseek(fds,event_next,SEEK_SET); ftell(fds); )

Insert Event: 30
Update Event: 31
Delete Event: 32
Map Event: 19
Gtid Event: 33

event_size > 44: 偏移 FLAGS_OFFSET = 19  - LOG_POS_OFFSET = 17 , GTID_FLAG =  26

 

 

总结MySQL服务器层面影响主从复制情况: 

1.  从库的系统时间被修改比当前时间更大(推荐配置时间服务器)

2.  在MTS设置不合理slave_checkpoint_period 参数

3. 主库大事务的sql语句性能:  延迟不会从0开始 而是直接从主库执行了当前事务多长时间开始。例如主库执行这个事务花费的20秒,那么延迟就会从20开始 , 导致 Query Event中没有准确执行时间 . ( 从这里参考 (3) mi->rli->last_master_timestamp ) 

4. 大表DDL: 延迟会从0开始,因为Query Event记录了准确的执行时间。

5. slave_rows_search_algorithms 参数 , 表没有主键或者唯一键,就不要设置INDEX_SCAN,HASH_SCAN

6. slave_checkpoint_period ( 默认 300ms) 在MTS中的Seconds_Behind_Master计算和检查点有关。( 参考 • DML (MTS) )

7. 根据 线程模式 , binlog事务模式, recovery_relay_log , sync_master_info , sync_relay_log , sync_relay_log_info 进行一个性能判断,如下:

 8. 表没有主键或者唯一键造成的延迟。这种情况不要以为设置slave_rows_search_algorithms参数为 INDEX_SCAN,HASH_SCAN , HASH_SCAN在有索引且一个事务中 的 update/delete的数据关键字重复值多才能提升性能

 9. 长时间不提交的事务可能造成延迟瞬间增加,因为GTID_EVENT和XID_EVENT是提交时间,而其他Event是命令发起的时间。

10. binlog_group_commit_sync_delay 的高值可能会影响多线程从库中的 slave worker 性能,但必须考虑主服务器的吞吐量和从服务器的吞吐量。还可以减少对具有binlog的任何服务器(主服务器或从服务器)上的binlog的 fsync() 调用次数。必须配合 slave_parallel_type=LOGICAL_CLOCK 

11. 在旧版本MySQL的主服务器和新版本MySQL的从服务器之间复制。

12. 启动 I/O 线程后人为的修改从库服务器的时间

13. 关闭 slave_preserve_commit_order 参数 出现 gap ,检查点只能停留 在 gap 之前的一个事务,可能后面的事务已经执行完成了。开启 slave_preserve_commit_order和开启log_slave_updates 防止在MTS复制模式下防止从库形成gap,导致主从数据不一致问题,交验和修正数据也是要导致延迟。

rpl_slave.cc
extern "C" void *handle_slave_sql(void *arg)

......

if (opt_slave_preserve_commit_order && rli->opt_slave_parallel_workers > 0 &&
      opt_bin_log && opt_log_slave_updates)
    commit_order_mngr= new Commit_order_manager(rli->opt_slave_parallel_workers);

  rli->set_commit_order_manager(commit_order_mngr);

 

14.  binlog_row_image设置minimal 在不修改非空唯一索引和主键时候的字段时候 binlog是不包含非空唯一索引和主键的字段

15. recovery_relay_log = 0 打破 relay log 和binary log的事务是连续性,recovery_relay_log = 1 relay log 和binary log当前满了也不能切换


 

100. 所以我最终迁移到PXC 或者 MGR 再或者迁移到 PostgreSQL物理流复制延迟时间也是十分低 (主从模式)解决上述主从复制延迟问题

待续....

binlog_group_commit_sync_delay 的高值可能会影响多线程从库中的 slave worker 性能。

原文出处:https://www.cnblogs.com/kelvin19840813/p/12257165.html

展开阅读全文
打赏
0
0 收藏
分享
加载中
更多评论
打赏
0 评论
0 收藏
0
分享
返回顶部
顶部