mysql binlog 日誌詳解，恢復測試
二進位制日誌常用引數：
max_binlog_size ：單個二進位制日誌檔案的最大值，超過該值，則產生新的二進位制日誌檔案，並記錄到.index檔案，預設1G。 binlog_cache_size: 使用InnoDB時，所有未提交的事務會記錄到一個快取中，等待事務提交時，直接將緩衝中的二進位制日誌寫入二進位制日誌檔案， 而該緩衝的大小由binlog_cache_size決定，binlog_cache_size是基於會話的，即：當一個執行緒開始一個事務時，mysql會自動分配一個大小為binlog_cache_size大小的快取，因此該值得設定需要相當小心，可以通過show global status 檢視binlog_cache_use、binlog_cache_disk_use的狀態，來判斷當前binlog_cache_size的設定是否合適。
sync_binlog：引數sync_binlog=[N]表示每寫快取多少次就同步到磁碟，如果將N設定為1，則表示採用同步寫磁碟的方式來寫二進位制日誌。該引數設定為1時，也應該將innodb_support_xa設為1來解決，這可以確保二進位制日誌和InnoDB儲存引擎資料檔案的同步。 binlog-do-db：該binlog-do-db=test引數表示的是，二進位制日誌記錄test庫。 binlog-ignore-db：該binlog-ignore-db=test，表示忽略test庫，不寫入二進位制日誌。 log-slave-update：搭建master=>slave=>slave的架構時，需要配置，也就是說，應用主的binlog也寫入自己的二進位制日誌中，方便自己的slave來同步日誌。 binlog_format：表示的是，二進位制日誌模式：ROW，STATEMENT，MIXED。 log_bin：二進位制日誌的路徑和名稱。 expire_logs_days = 7 binlog過期清理時間。
二進位制日誌格式比較：
1.Statement：每一條會修改資料的sql都會記錄在binlog中。 優點：不需要記錄每一行的變化，減少了binlog日誌量，節約了IO，提高效能。(相比row能節約多少效能與日誌量，這個取決於應用的SQL情況，正常同一條記錄修改或者插入row格式所產生的日誌量還小於Statement產生的日誌量，但是考慮到如果帶條件的update操作，以及整表刪除，alter表等操作，ROW格式會產生大量日誌，因此在考慮是否使用ROW格式日誌時應該跟據應用的實際情況，其所產生的日誌量會增加多少，以及帶來的IO效能問題。)
缺點：由於記錄的只是執行語句，為了這些語句能在slave上正確執行，因此還必須記錄每條語句在執行的時候的一些相關資訊，以保證所有語句能在slave得到和在master端執行時候相同的結果。另外mysql 的複製,像一些特定函式功能，slave可與master上要保持一致會有很多相關問題 (如sleep()函式， last_insert_id()，以及user-defined functions(udf)會出現問題)。
還有一點，statement只記錄了SQL語句，我們通過日誌也只能看到他執行的SQL，但無法獲知SQL修改之前的資料。
使用以下函式的語句也無法被複制： LOAD_FILE()、 UUID()、 USER()、 FOUND_ROWS()、 SYSDATE() ,now()(除非啟動時啟用了 --sysdate-is-now 選項) 同時在INSERT ...SELECT 會產生比 RBR 更多的行級鎖。
2.Row:不記錄sql語句上下文相關資訊，僅儲存哪條記錄被修改。此時可以將InnoDB的事務隔離基本設為READ COMMITTED，以獲得更好的併發性。
優點： binlog中可以不記錄執行的sql語句的上下文相關的資訊，僅需要記錄那一條記錄被修改成什麼了。所以rowlevel的日誌內容會非常清楚的記錄下每一行資料修改的細節。而且不會出現某些特定情況下的儲存過程，或function，以及trigger的呼叫和觸發無法被正確複製的問題。
缺點:所有的執行的語句當記錄到日誌中的時候，都將以每行記錄的修改來記錄，這樣可能會產生大量的日誌內容,比如一條update語句，修改多條記錄，則binlog中每一條修改都會有記錄，這樣造成binlog日誌量會很大，新版本的MySQL中對row level模式也被做了優化，並不是所有的修改都會以row來記錄，像遇到表結構變更的時候就會以statement模式來記錄。至於update或者delete等修改資料的語句，還是會記錄所有行的變更。
3.Mixed: 是以上兩種level的混合使用，一般的語句修改使用statment格式儲存binlog，如一些函式，statement無法完成主從複製的操作，則採用row格式儲存binlog,MySQL會根據執行的每一條具體的sql語句來區分對待記錄的日誌形式，也就是在Statement和Row之間選擇一種。
清除slave複製資訊： reset slave all;
MySQL [(none)]> show binary logs; +------------+-----------+ | Log_name | File_size | +------------+-----------+ | bin.000001 | 100139 | | bin.000002 | 100139 | | bin.000003 | 101198 | | bin.000004 | 929 | +------------+-----------+ 4 rows in set (0.03 sec)
檢視binlog日誌：show binlog events in 'mysqld-bin.000002'\G; 檢視mysqld-bin.000002檔案所有二進位制日誌。 SHOW BINLOG EVENTS [IN 'log_name'] [FROM pos] [LIMIT [offset,] row_count]
MySQL [(none)]> show binlog events in 'bin.000002' from 99536 limit 0,3\G; *************************** 1. row *************************** Log_name: bin.000002 Pos: 99536 Event_type: Query Server_id: 11 End_log_pos: 99687 Info: use `mysql`; CREATE USER 'root'@'localhost' IDENTIFIED WITH 'mysql_native_password' *************************** 2. row *************************** Log_name: bin.000002 Pos: 99687 Event_type: Anonymous_Gtid Server_id: 11 End_log_pos: 99752 Info: SET @@SESSION.GTID_NEXT= 'ANONYMOUS' *************************** 3. row *************************** Log_name: bin.000002 Pos: 99752 Event_type: Query Server_id: 11 End_log_pos: 99903 Info: use `mysql`; GRANT ALL PRIVILEGES ON *.* TO 'root'@'localhost' WITH GRANT OPTION 3 rows in set (0.00 sec)
檔案檢視： mysqlbinlog /usr/local/mysql/binlog/mysql-bin.000042 >/tmp/000042.sql \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\ # at 467 事件起點。 #151113 12:31:56 server id 30 end_log_pos 1073 Query thread_id=73185 exec_time=0 error_code=0 #151113 12:31:56事件發生時間點。事件pos，thread_id，執行時間，錯誤程式碼等資訊 use `ads_uuid`/*!*/; 執行的SQL SET TIMESTAMP=1447389116/*!*/; 事務執行的時間戳。 SET @@session.pseudo_thread_id=73185/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=2097152/*!*/; 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/*!*/; 執行語句session相關。 UPDATE device SET id=893390,me='867622020128842',pn='Qualcomm',md='2014811' where id='893390' 執行SQL語句 /*!*/; # at 1073 #151113 12:31:56 server id 30 end_log_pos 1100 Xid = 120978366 COMMIT/*!*/;
\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\ 1.開始事物的時間: SET TIMESTAMP=1350355892/*!*/; BEGIN
2.sql event起點 #at 1643330 :為事件的起點，是以1643330位元組開始。
3.sql event 發生的時間點 #151113 12:31:56 是事件發生的時間，
4.serverId server id 30 :為master 的serverId
5.sql event終點及花費時間，錯誤碼 end_log_pos 1643885:為事件的終點，其中1643885 就是下一個#at事件發生的起點。 execTime 0: 花費的時間 error_code=0:錯誤碼 Xid:事件指示提交的XA事務
Mixed日誌說明：
在slave日誌同步過程中，對於使用now這樣的時間函式，MIXED日誌格式，會在日誌中產生對應的unix_timestamp()*1000的時間字串，slave在完成同步時，取用的是sqlEvent發生的時間來保證資料的準確性。另外對於一些功能性函式slave能完成相應的資料同步，而對於上面指定的一些類似於UDF函式，導致Slave無法知曉的情況，則會採用ROW格式儲存這些Binlog，以保證產生的Binlog可以供Slave完成資料同步。 ================================================================================================
一、基於RBR行復制是與記錄的位置有關，binlog裡只記錄了了相關表發生變化的列的資料，對此引入了4個事件： Table_map、Write_rows、Update_rows、Delete_rows。
Table_map事件(包含表的ID、表名和列的型別，沒有列名),再後面是3個事件，最後是結束標誌為STMT_END_F。
如果是ROW格式，日誌是這樣的： \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\ BEGIN /*!*/; # at 1110 # at 1278 #151113 11:10:27 server id 105 end_log_pos 1278 Table_map: `mysql`.`user` mapped to number 4 #151113 11:10:27 server id 105 end_log_pos 1676 Delete_rows: table id 4 flags: STMT_END_F
BINLOG ' o1RFVhNpAAAAqAAAAP4EAAAAAAQAAAAAAAEABW15c3FsAAR1c2VyACz+/v7+/v7+/v7+/v7+/v7+ /v7+/v7+/v7+/v7+/v7+/v78/PwDAwMD/vz+/kz+tP7w/in3AfcB9wH3AfcB9wH3AfcB9wH3AfcB 9wH3AfcB9wH3AfcB9wH3AfcB9wH3AfcB9wH3AfcB9wH3AfcB9wECAgL+QAL3AfcBAAAAAAAA o1RFVhlpAAAAjgEAAIwGAAAAAAQAAAAAAAEALP///////wAAAAAA8AkxMjcuMC4wLjEEY21vbikq RTc0ODU4REI4NkVCQTIwQkMzM0QwQUVDQUU4QTgxMDhDNTZCMTdGQQICAgICAgICAgICAgICAgIC AgICAgICAgICAgICAQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABAQAAAAAA8Alsb2NhbGhvc3QE Y21vbikqRTc0ODU4REI4NkVCQTIwQkMzM0QwQUVDQUU4QTgxMDhDNTZCMTdGQQICAgICAgICAgIC AgICAgICAgICAgICAgICAgICAQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABAQAAAAAA8A0xOTIu MTY4LjEuMjI1BGNtb24pKkU3NDg1OERCODZFQkEyMEJDMzNEMEFFQ0FFOEE4MTA4QzU2QjE3RkEC AgICAgICAgICAgICAgICAgICAgICAgICAgICAgEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAQE= '/*!*/; ------這中間是一段程式碼 # at 1676 #151113 11:10:27 server id 105 end_log_pos 1746 Query thread_id=11 exec_time=0 error_code=0 SET TIMESTAMP=1447384227/*!*/; /*!\C utf8mb4 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=45/*!*/; COMMIT /*!*/; # at 1746 #151113 11:38:08 server id 106 end_log_pos 1784 GTID 0-106-346 \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\ 以上我們可以清楚的看到。沒有任何SQL語句，也沒有看到修改的具體資料。
MariaDB [(none)]> show binlog events in 'mysql-bin.000042' from 1278 limit 4 \G *************************** 1. row *************************** Log_name: mysql-bin.000042 Pos: 1278 Event_type: Delete_rows_v1 Server_id: 105 End_log_pos: 1676 Info: table_id: 4 flags: STMT_END_F *************************** 2. row *************************** Log_name: mysql-bin.000042 Pos: 1676 Event_type: Query Server_id: 105 End_log_pos: 1746 Info: COMMIT *************************** 3. row *************************** Log_name: mysql-bin.000042 Pos: 1746 Event_type: Gtid Server_id: 106 End_log_pos: 1784 Info: GTID 0-106-346 *************************** 4. row *************************** Log_name: mysql-bin.000042 Pos: 1784 Event_type: Query Server_id: 106 End_log_pos: 1866 Info: use `db`; truncate table t
如何讓ROW格式的日誌，顯示他的廬山真面目呢：
mysqlbinlog --base64-output=decode-rows -v /usr/local/mysql/binlog/mysql-bin.000042 >/tmp/000042.sql
--base64-output=decode-rows：就是解析BINLOG '後面那一長串字元的。-v顯示解析結果。 =========================================================================================================== # at 1904 # at 1945 #151113 11:38:35 server id 106 end_log_pos 1945 Table_map: `db`.`t` mapped to number 92 #151113 11:38:35 server id 106 end_log_pos 1982 Write_rows: table id 92 flags: STMT_END_F ### INSERT INTO `db`.`t` ### SET ### @1=2 ### @2='ll' # at 1982 #151113 11:38:35 server id 106 end_log_pos 2009 Xid = 6968 COMMIT/*!*/; # at 2009 #151113 15:12:51 server id 106 end_log_pos 2047 GTID 0-106-348 /*!100001 SET @@session.gtid_seq_no=348*//*!*/; BEGIN /*!*/; # at 2047 # at 2088 #151113 15:12:51 server id 106 end_log_pos 2088 Table_map: `db`.`t` mapped to number 92 #151113 15:12:51 server id 106 end_log_pos 2125 Write_rows: table id 92 flags: STMT_END_F ### INSERT INTO `db`.`t` ### SET ### @1=4 ### @2='oo' # at 2125 #151113 15:12:51 server id 106 end_log_pos 2152 Xid = 6978 COMMIT/*!*/; DELIMITER ; =========================================================================================================================主要是方便我們分析，解析出了執行的資料。
檢視日誌：/usr/local/mysql/3307/bin/mysqlbinlog --no-defaults --base64-output=decode-rows -v /log/binlog/3307/bin.000004 >/tmp/3307.sql # at 2202 #160523 17:37:59 server id 11 end_log_pos 2246 CRC32 0xf5999189 Table_map: `test`.`t` mapped to number 211 # at 2246 #160523 17:37:59 server id 11 end_log_pos 2286 CRC32 0x308897a3 Write_rows: table id 211 flags: STMT_END_F ### INSERT INTO `test`.`t` ### SET ### @1=1001 # at 2286 #160523 17:37:59 server id 11 end_log_pos 2317 CRC32 0xdc9367e9 Xid = 201 COMMIT/*!*/; # at 2317 #160523 17:40:19 server id 11 end_log_pos 2382 CRC32 0xc99d11d2 GTID last_committed=9 sequence_number=10 SET @@SESSION.GTID_NEXT= '3c7ce82b-18be-11e6-ba0a-0050569e70f2:143'/*!*/; # at 2382 #160523 17:40:19 server id 11 end_log_pos 2459 CRC32 0x2ddc09f8 Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1463996419/*!*/; BEGIN /*!*/; # at 2459 # at 2509 #160523 17:40:19 server id 11 end_log_pos 2553 CRC32 0xe2ad52d0 Table_map: `test`.`t` mapped to number 212 # at 2553 #160523 17:40:19 server id 11 end_log_pos 2593 CRC32 0xffb7d75d Write_rows: table id 212 flags: STMT_END_F ### INSERT INTO `test`.`t` ### SET ### @1=9999 # at 2593 #160523 17:40:19 server id 11 end_log_pos 2624 CRC32 0x2b09846c Xid = 223 COMMIT/*!*/; # at 2624 #160523 17:40:27 server id 11 end_log_pos 2689 CRC32 0x46dd7674 GTID last_committed=10 sequence_number=11 SET @@SESSION.GTID_NEXT= '3c7ce82b-18be-11e6-ba0a-0050569e70f2:144'/*!*/; # at 2689 #160523 17:40:27 server id 11 end_log_pos 2766 CRC32 0x657dd679 Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1463996427/*!*/; BEGIN /*!*/; # at 2766 # at 2816 #160523 17:40:27 server id 11 end_log_pos 2860 CRC32 0xe0b8b86f Table_map: `test`.`t` mapped to number 212 # at 2860 #160523 17:40:27 server id 11 end_log_pos 2900 CRC32 0x83236ed8 Write_rows: table id 212 flags: STMT_END_F ### INSERT INTO `test`.`t` ### SET ### @1=8888 # at 2900 #160523 17:40:27 server id 11 end_log_pos 2931 CRC32 0xbf47abdd Xid = 224 COMMIT/*!*/;
我們這裡知道現在資料庫中的資料是1001最後一條，所以，這裡我們就知道從哪裡開始恢復。
/data0/mysql/bin/mysqlbinlog --start-datetime='2017-12-20 18:00:00' --base64-output=decode-rows -vv /data0/mysql/data/mysql-bin.000020 >20.sql
/usr/local/mysql/3307/bin/mysqlbinlog --no-defaults --start-position=2317 /log/binlog/3307/bin.000004 | mysql -uroot -p -S /usr/local/mysql/3307/mysql.sock執行之後，發現並沒有恢復。 實際上，是gtid的問題： /usr/local/mysql/3307/bin/mysqlbinlog --no-defaults --skip-gtids --stop-position=1498 /log/binlog/3307/bin.000010 | mysql -uroot -p -S /usr/local/mysql/3307/mysql.sock 新增--skip-gtids就可以完成。
[[email protected] ~]# /usr/local/mysql/3307/bin/mysqlbinlog --no-defaults --base64-output=decode-rows -v --start-position=2317 -vv /log/binlog/3307/bin.000004 | grep "insert into" # insert into t values(9999) # insert into t values(8888)
[[email protected] ~]# /usr/local/mysql/3307/bin/mysqlbinlog --no-defaults --base64-output=decode-rows --start-position=2317 -vv /log/binlog/3307/bin.000004 | grep "insert into" | sed -e 's/#//g'|sed -e 's/)/);/g' insert into t values(9999); insert into t values(8888);
Mariadb10.0是OK的，但是mysql 5.7.12恢復不了。
5.7.12 指定--stop-position的時候，需要注意：指定的pos位置。 Log_name: bin.000010 Pos: 947 Event_type: Query Server_id: 11 End_log_pos: 1024 Info: BEGIN *************************** 17. row *************************** Log_name: bin.000010 Pos: 1024 Event_type: Rows_query Server_id: 11 End_log_pos: 1084 Info: # insert into tab(name) values ('pol') *************************** 18. row *************************** Log_name: bin.000010 Pos: 1084 Event_type: Table_map Server_id: 11 End_log_pos: 1133 Info: table_id: 112 (test.tab) *************************** 19. row *************************** Log_name: bin.000010 Pos: 1133 Event_type: Write_rows Server_id: 11 End_log_pos: 1177 Info: table_id: 112 flags: STMT_END_F *************************** 20. row ***************************
像上面這樣，指定的--stop-position只能是1177這個位置。否則要報告警： WARNING: The range of printed events ends with a row event or a table map event that does not have the STMT_END_F flag set. This might be because the last statement was not fully written to the log, or because you are using a --stop-position or --stop-datetime that refers to an event in the middle of a statement. The event(s) from the partial statement have not been written to output. 也就是說，需要指定到STMT_END_F flag的位置。
==================== 最好不要這樣恢復： shell> mysqlbinlog binlog.000001 | mysql -u root -p shell> mysqlbinlog binlog.000002 | mysql -u root -p 處理二進位制日誌使用的伺服器不同的連線這樣可能會導致問題，如果第一個日誌檔案包含一個CREATE TEMPORARY TABLE語句和第二日誌包含使用臨時表的語句。 當第一個mysql程序終止時，伺服器會刪除臨時表。當第二個mysql程序嘗試使用該表時，伺服器報告“unknown table”。 為了避免這樣的問題，使用一個連線來執行想要處理的所有二進位制日誌中的內容。這裡就是這樣做的一種方法：
shell> mysqlbinlog binlog.000001 binlog.000002 | mysql -u root -p
另一種方法是寫的所有日誌到一個檔案中，然後處理檔案： shell> mysqlbinlog binlog.000001 > /tmp/statements.sql shell> mysqlbinlog binlog.000002 >> /tmp/statements.sql shell> mysql -u root -p -e "source /tmp/statements.sql"