mysqlbinlog工具使用的幾個疑惑點和解釋

1、Format_description_event問題：

BINLOG kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTWkTXkUyAKAAAALQAAAOgEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck/*!*/;

假設以上是使用 ../mysql/bin/mysqlbinlog -v --start-position=1094 mysql-bin.000036生成的一個BINLOG，類型為 DELETE_ROW_LOG_EVENT。內容如下：

### DELETE FROM `test`.`t3`### WHERE### @1=1### DELETE FROM `test`.`t3`### WHERE### @1=2

mysql客戶端，單獨執行這個binlog無法達到刪除t3中 (1), (2)這兩行的目的。報錯如下：

mysql> BINLOG kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTWkTXkUyAKAAAALQAAAOgEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck/*!*/;ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.mysql>

DBA剛開始誤以為是個mysql bug。其實不然。

錯誤提示需要先執行format description BINLOG，即需要先執行Format_description_event，該binlog用於描述接下來要執行的BINLOG的版本等信息，如下：

# at 4#140808 10:26:53 server id 10 end_log_pos 121 CRC32 0x5731b21e Start: binlog v 4, server v 5.6.19-log created 140808 10:26:53# Warning: this binlog is either in use or was not closed properly.BINLOG bTXkUw8KAAAAdQAAAHkAAAABAAQANS42LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXQAEGggAAAAICAgCAAAACgoKGRkADQEesjFX/*!*/;

該BINLOG位於每個binlog文件偏移位置4開始。

似乎是合理的，在mysql-5.5.30版本中，DBA第二次執行原來的DELETE_ROW_LOG_EVENT時，卻能夠執行成功。這似乎不合理。其實第二次執行也不應該成功，這是mysql-5.5.30的一個bug

鏈接為：Bugs : Percona Server

在mysql 5.6.19驗證了下，該bug已經修復：

mysql> BINLOG kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck/*!*/;ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.mysql> BINLOG kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck/*!*/;ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.mysql> mysql> BINLOG kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck/*!*/;ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.mysql>

即不管執行多少次同一個BINLOG，都無法成功。除非先執行了Format_description_event：

mysql> BINLOG > bTXkUw8KAAAAdQAAAHkAAAABAAQANS42LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA > AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXQAEGggAAAAICAgCAAAACgoKGRkADQEe > sjFX > /*!*/; //這是一個Format_description_eventQuery OK, 0 rows affected (0.00 sec)mysql> BINLOG > kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW > kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck > /*!*/;Query OK, 0 rows affected (0.00 sec)

2、執行binlog時「0 rows affected」問題

這樣就成功得將對應的t3中對應的(1),(2)刪掉。但問題也來了，為什麼執行完顯示 「Query OK, 0 rows affected (0.00 sec)」。這個讓人很費解。

「0 rows affected」 這個問題，也是有DBA提出來了，他們在使用mysqlbinlog -B 進行flashback操作時，執行過程一直是「Query OK, 0 rows affected (0.00 sec)」，懷疑

flashback功能出了問題。其實是因為執行BINLOG直接調用存儲引擎的相關介面，跟常規的sql語句執行走的代碼路徑不完全相同，所以rows affected沒有得到正確統計。

繼續回到Format_description_event問題上，需要注意的是，在一次客戶端連接期間，只需執行一次Format_description_event即可。這個也是好理解的。

3、flashback功能需要與-v配合使用問題

不過mysql的flashback工具確實存在一個問題，就是在flashback update 操作時，需要-v和-B一起作用才能夠成功。這是因為：

Rows_log_event::exchange_update_rows在進行set和where內容調換時，需要計算這兩段內容的長度，該功能由Rows_log_event::print_verbose_one_row完成，

該函數會根據表定義table_def (td)來獲取表中每個field的length，並通過binlog中的記錄獲取set和where中那幾個field是NULL的。

而td是從Table_map_log_event中獲取的，且只有在-v時才會生成td：

if (print_event_info->verbose) { Rows_log_event *ev= NULL; Log_event_type et= (Log_event_type) ptr[EVENT_TYPE_OFFSET]; if (checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF && checksum_alg != BINLOG_CHECKSUM_ALG_OFF) size-= BINLOG_CHECKSUM_LEN; // checksum is displayed through the header switch(et) { case TABLE_MAP_EVENT: { Table_map_log_event *map; map= new Table_map_log_event((const char*) ptr, size, glob_description_event); print_event_info->m_table_map.set_table(map->get_table_id(), map);break; }

通過set_table(map->get_table_id(), map)來將對應的map（ td從這裡來map->create_table_def() ）放入table的哈希表中；

所以，不加-v進行update操作的flashback解析時，由於無法通過map= print_event_info->m_table_map.get_table(m_table_id)來獲取map進而獲取td。

導致無法知道表定義，從而無法進行set和where長度的計算並進行內容調換。

為了修復這個bug，修改如下：

if (is_flashback) //Flashback { uint32 fb_size = size;if (checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF && checksum_alg != BINLOG_CHECKSUM_ALG_OFF)fb_size-= BINLOG_CHECKSUM_LEN; // checksum is displayed through the header switch (ptr[EVENT_TYPE_OFFSET]) { //add TABLE_MAP_EVENT, as UPDATE_ROWS_EVENT need to get_table from map case TABLE_MAP_EVENT: {Table_map_log_event *map; map= new Table_map_log_event((const char*) ptr, fb_size, glob_description_event);print_event_info->m_table_map.set_table(map->get_table_id(), map);break; } case WRITE_ROWS_EVENT: ptr[EVENT_TYPE_OFFSET]= DELETE_ROWS_EVENT; break;.... if (print_event_info->verbose) { Rows_log_event *ev= NULL; Log_event_type et= (Log_event_type) ptr[EVENT_TYPE_OFFSET]; if (checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF && checksum_alg != BINLOG_CHECKSUM_ALG_OFF) size-= BINLOG_CHECKSUM_LEN; // checksum is displayed through the header switch(et) { case TABLE_MAP_EVENT: { //if flashback, map has already set into hash above if (!is_flashback) { Table_map_log_event *map; map= new Table_map_log_event((const char*) ptr, size, glob_description_event); print_event_info->m_table_map.set_table(map->get_table_id(), map); } break; }

4、mysqlbinlog解析relay log報「unknown table」問題

組內的小夥伴在做基於relay-log進行的資料庫實例故障恢復時，發現mysqlbinlog的又一個bug，社區之前也已提及，如下：row based relay log events are lost from mysqlbinlog output。大意是在使用mysqlbinlog解析高可用資料庫實例從庫的relay log時，提示「### Row event for unknown table #16#」，簡單分析可知該提示是說DML操作（UPDATE/INSERT/DELETE）所需的table map找不到了，而table map可以將table id（上述的16）跟表定義建立關聯。沒有table map當然就無法解析DML操作。

那麼table map真的不見了嗎？其實不然，只是table map位於上一個relay log文件而已。那麼，既然mysqlbinlog能夠同時解析多個文件，能不能將上一個文件跟當前文件一起解析，這樣應該就不會報這個錯誤了吧。我剛開始也是這麼認為的，還跟小夥伴爭了，結果應了那句：「沒有調查就沒有發言權」。小夥伴可是試驗過了，結果還是無法解析。個人覺得這不合理啊。

為此，看了mysqlbinlog的代碼，很快就找到了問題所在，下面進行簡單分析

1、mysqlbinlog用一個for循環來處理一個或多個binlog文件，如下：

// main loop:

for (save_stop_position= stop_position, stop_position= ~(my_off_t)0 ; (--argc >= 0) ; )

{

if (argc == 0) // last log, --stop-position applies stop_position= save_stop_position;

if ((retval= dump_log_entries(*argv++)) != OK_CONTINUE)

break;

// For next log, --start-position does not apply

start_position= BIN_LOG_HEADER_SIZE;

}

這個循環代碼很是簡練，以至於剛開始看代碼的還是，根本不知道是什麼意思。其實，循環中argc表示有幾個binlog文件需要解析，*argv表示具體的文件名稱。start-position和stop_position處理得也很奇妙，在此不細說。

2、有以上的鋪墊可以知道，dump_log_entries函數是用來處理每個binlog文件的。

/** High-level function for dumping a named binlog. This function calls dump_remote_log_entries() or dump_local_log_entries() to do the job. @param[in] logname Name of input binlog. @retval ERROR_STOP An error occurred - the program should terminate. @retval OK_CONTINUE No error, the program should continue. @retval OK_STOP No error, but the end of the specified range of events to process has been reached and the program should terminate.*/static Exit_status dump_log_entries(const char* logname){ Exit_status rc; PRINT_EVENT_INFO print_event_info; if (!print_event_info.init_ok()) return ERROR_STOP; if (!only_event_info) { /* Set safe delimiter, to dump things like CREATE PROCEDURE safely */ fprintf(result_file, "DELIMITER /*!*/;
"); strmov(print_event_info.delimiter, "/*!*/;"); } print_event_info.verbose= short_form ? 0 : verbose; rc= (remote_opt ? dump_remote_log_entries(&print_event_info, logname) : dump_local_log_entries(&print_event_info, logname)); if (!only_event_info) { if (!flashback_opt) { /* Set delimiter back to semicolon */ fprintf(result_file, "DELIMITER ;
"); strmov(print_event_info.delimiter, ";"); } } return rc;}

根據解析的binlog是否為遠程的，又分為dump_remote_log_entries和dump_local_log_entries，我們主要用了dump_local_log_entries，進入函數後我們會發現，mysqlbinlog使用Log_event::read_log_event(file, glob_description_event)和process_event(print_event_info, ev, old_off, logname)兩個函數來讀取、構建和解析每個binlog。我們應該關注的是print_event_info，這個是控制整個解析過程的關鍵對象。比如說，如果binlog的類型是TABLE_MAP_EVENT （這個就是問題所在，保存table map的地方），那麼在解析時，會將table id和具體的表定義聯繫起來。並記錄到print_event_info中。process_event在處理WRITE_ROWS_EVENT/UPDATE_ROWS_EVENT/DELETE_ROWS_EVENT(對應前述的DML操作)時，由於event中僅記錄所操作的表的table id，所以就需要藉助print_event_info來獲取對應的映射關係。跨relay log的事務在使用mysqlbinlog進行解析時出錯的原因就在於，print_event_info是在dump_log_entries中定義的。在完成一個binlog文件的解析後會自動銷毀掉，無法繼承給下一個待解析的binlog文件。

所以，解決問題的辦法很簡單，將PRINT_EVENT_INFO print_event_info定義提取出來，設為mysqlbinlog的全局變數即可解決問題。

之前有小夥伴提問，為什麼不把表定義直接記錄到DML操作中，答案是顯而易見的，如果每個DML的binlog都記錄表定義，一是沒有必要，二是太浪費存儲空間了。
推薦閱讀：