1. 程式人生 > >大事務造成的延遲(從binlog入手分析)

大事務造成的延遲(從binlog入手分析)

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;

主庫

從庫
GTID_EVENT
T1+Commit時間
延遲 T2-(T1+Commit時間)
QUERY_EVENT
T1
延遲 T2-T1
MAP_EVENT
T1
延遲 T2-T1
DELETE_EVENT
T1
延遲 T2-T1
XID_EVENT
T1+Commit時間
延遲 T2-(T1+Commit時間)

binlog_event.h
class Log_event_header
·timeval:固定4位元組,是新紀元時間(1970年1月1日0時0分0秒)以來的秒數。這個時
間是命令發起的時間。如何定義命令發起呢?它是執行計劃生成後開始實際執行語句的
時候。原始碼可以是在dispatch一command函式的開頭設定的(thd->set-time())。言外
之意對於語法意義、許可權橙查、優化器生成執行計劃的時間都包括在裡面。其次要注意
了這個時間在從庫計算Seconds一Behind一Master的時候是一個重要的依據,這一點我們
將在第27節詳細討論。
·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_DESCR丨PTION_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
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的FDE用於在Slave上建立FDE事件,該事件將在此處寫入。 在這種情況下,我們可能最終會讀取更多位元組,如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部分也可能多個。(參考圖6-2)


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、重點 EventGTIDJ_LOG_EVENT
注意:本文分為正文和附件兩部分,都是圖片格式,如果正文有圖片不清晰可以將附件的圖片 儲存到本地檢視。
本節比較簡單因為GTID_LOG_EVENT和ANONYMOUS_GTID_LOG_EVENT格式一致,只是 攜帶的資料不一樣而已,我們只解釋GTID_LOG_EVENT即可
一、GTID LOG EVENT
(1) GTID_LOG_EVENT的作用
GTID的作用我們前面已經說過了,後面還會提及。這裡我們只需要知道GTID_LOG_EVENT 這個Event主要記錄的部分有下面三個:

• GTID的詳細倌息。
• 邏輯時鐘詳細倍息,即last commit和seq number
• 是否為行模式,比如DDL語句就不是行模式的

我們需要注意顯示開啟事務的情況下GTID_LOG_EVENT和XID_EVENT Event header的 timestamp都是commit命令發起的時間,當然如果沒有顯示開啟事務那麼timestamp還是命 令發起的時間。

 

 

固定部分
• flags: 1位元組。主要用於表示是否是行模式的,如果是則為0X00。不是則為0X01,注意 DDL都不是行模式的,而是語句模式^
• server_uuid: 16位元組。server_uuid引數去掉中間的16進製表示。
• gno: 8位元組。小端顯示。表示GTID的序號。
• ts type: 1位元組•固定為02。
• last commit: 8位元組。小端顯示。
• seq number: 8位元組。小端顯示。
關於last commit和seq number的生成方式會在後面第15節和第16節進行詳細描述。

(4)簡單解析
下面是一個的GTID_LOG_EVEN丁(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
};

 

待續!

&n