binlog之五:mysqlbinlog解析binlog亂碼問題解密


發現MySQL庫的binlog日志出來都是亂碼,如下所示: 
BINLOG ’ 
IXZqVhNIAAAALQAAAGcBAAAAAHoAAAAAAAEABHRlc3QAAno0AAEDAABUOcnY 
IXZqVh5IAAAAKAAAAI8BAAAAAHoAAAAAAAEAAgAB//4BAAAAcu+UpA==,如果強行用-v出來也得不到具體執行的sql語句,這個問題困擾了很近,今天深入研究才發現核心問題所在。


1,binlog日志的困擾,先看下日志格式

mysql> show variables like '%binlog%'; +-----------------------------------------+----------------------+ | Variable_name | Value | +-----------------------------------------+----------------------+ | binlog_cache_size | 1048576 | | binlog_checksum | CRC32 | | binlog_direct_non_transactional_updates | OFF | | binlog_format | MIXED | | binlog_max_flush_queue_time | 0 | | binlog_order_commits | ON | | binlog_row_image | FULL | | binlog_rows_query_log_events | OFF | | binlog_stmt_cache_size | 32768 | | innodb_api_enable_binlog | OFF | | innodb_locks_unsafe_for_binlog | OFF | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 1073741824 | | max_binlog_stmt_cache_size | 18446744073709547520 | | sync_binlog | 1 | +-----------------------------------------+----------------------+ 15 rows in set (0.01 sec) mysql> 

日志格式是MIXED的,這個表示一些特殊的uuid以及now()之類會記錄成row,其它的仍然是記錄sql模式。


2,測試例子:

mysql> use test;
Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql> create table z4 select 1 as a; Query OK, 1 row affected (0.02 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> insert into z4 select 2; Query OK, 1 row affected (0.00 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> 

3,查看binlog,打開是亂碼模式,看不到執行的sql語句,如下所示

[root@mysql5.6.12 binlog_new]# ll
總用量 32
-rw-rw----. 1 mysql mysql 143 12月 10 21:09 mysql-bin.000001 -rw-rw----. 1 mysql mysql 17549 12月 11 15:06 mysql-bin.000002 -rw-rw----. 1 mysql mysql 618 12月 11 15:07 mysql-bin.000003 -rw-rw----. 1 mysql mysql 135 12月 11 15:06 mysql-bin.index [root@mysql5.6.12 binlog_new]# /usr/local/mysql/bin/mysqlbinlog mysql-bin.000003 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #151211 15:06:46 server id 72 end_log_pos 120 CRC32 0x9961ff72 Start: binlog v 4, server v 5.6.12-log created 151211 15:06:46 # Warning: this binlog is either in use or was not closed properly. BINLOG ' BnZqVg9IAAAAdAAAAHgAAAABAAQANS42LjEyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAXL/ YZk= '/*!*/; # at 120 #151211 15:07:13 server id 72 end_log_pos 192 CRC32 0x3ea43b0e Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817633/*!*/; SET @@session.pseudo_thread_id=732/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1075838976/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; /*!\C utf8mb4 *//*!*/; SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #151211 15:07:13 server id 72 end_log_pos 314 CRC32 0xcaec51ae Query thread_id=732 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449817633/*!*/; CREATE TABLE `z4` ( `a` int(1) NOT NULL DEFAULT '0' ) /*!*/; # at 314 #151211 15:07:13 server id 72 end_log_pos 359 CRC32 0xd8c93954 Table_map: `test`.`z4` mapped to number 122 # at 359 #151211 15:07:13 server id 72 end_log_pos 399 CRC32 0xa494ef72 Write_rows: table id 122 flags: STMT_END_F BINLOG ' IXZqVhNIAAAALQAAAGcBAAAAAHoAAAAAAAEABHRlc3QAAno0AAEDAABUOcnY IXZqVh5IAAAAKAAAAI8BAAAAAHoAAAAAAAEAAgAB//4BAAAAcu+UpA== '/*!*/; # at 399 #151211 15:07:13 server id 72 end_log_pos 430 CRC32 0xd1ab5b55 Xid = 6908 COMMIT/*!*/; # at 430 #151211 15:07:20 server id 72 end_log_pos 502 CRC32 0xdfc3212d Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817640/*!*/; BEGIN /*!*/; # at 502 #151211 15:07:20 server id 72 end_log_pos 547 CRC32 0xc59aab0e Table_map: `test`.`z4` mapped to number 122 # at 547 #151211 15:07:20 server id 72 end_log_pos 587 CRC32 0x648b02a4 Write_rows: table id 122 flags: STMT_END_F BINLOG ' KHZqVhNIAAAALQAAACMCAAAAAHoAAAAAAAEABHRlc3QAAno0AAEDAAAOq5rF KHZqVh5IAAAAKAAAAEsCAAAAAHoAAAAAAAEAAgAB//4CAAAApAKLZA== '/*!*/; # at 587 #151211 15:07:20 server id 72 end_log_pos 618 CRC32 0x9b35600a Xid = 6915 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@mysql5.6.12 binlog_new]# 

PS:大家看到/usr/local/mysql/bin/mysqlbinlog mysql-bin.000003解析出來的都是KHZqVhNIAAAALQAAACMCAAAAAHoAAAA這樣的亂碼格式。


4,google,得知可以用–base64-output=DECODE-ROWS -v查看出來sql語句,如下所示

[root@mysql5.6.12 binlog_new]# /usr/local/mysql/bin/mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000003 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #151211 15:06:46 server id 72 end_log_pos 120 CRC32 0x9961ff72 Start: binlog v 4, server v 5.6.12-log created 151211 15:06:46 # Warning: this binlog is either in use or was not closed properly. # at 120 #151211 15:07:13 server id 72 end_log_pos 192 CRC32 0x3ea43b0e Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817633/*!*/; SET @@session.pseudo_thread_id=732/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1075838976/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; /*!\C utf8mb4 *//*!*/; SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #151211 15:07:13 server id 72 end_log_pos 314 CRC32 0xcaec51ae Query thread_id=732 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449817633/*!*/; CREATE TABLE `z4` ( `a` int(1) NOT NULL DEFAULT '0' ) /*!*/; # at 314 #151211 15:07:13 server id 72 end_log_pos 359 CRC32 0xd8c93954 Table_map: `test`.`z4` mapped to number 122 # at 359 #151211 15:07:13 server id 72 end_log_pos 399 CRC32 0xa494ef72 Write_rows: table id 122 flags: STMT_END_F ### INSERT INTO `test`.`z4` ### SET ### @1=1 # at 399 #151211 15:07:13 server id 72 end_log_pos 430 CRC32 0xd1ab5b55 Xid = 6908 COMMIT/*!*/; # at 430 #151211 15:07:20 server id 72 end_log_pos 502 CRC32 0xdfc3212d Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817640/*!*/; BEGIN /*!*/; # at 502 #151211 15:07:20 server id 72 end_log_pos 547 CRC32 0xc59aab0e Table_map: `test`.`z4` mapped to number 122 # at 547 #151211 15:07:20 server id 72 end_log_pos 587 CRC32 0x648b02a4 Write_rows: table id 122 flags: STMT_END_F ### INSERT INTO `test`.`z4` ### SET ### @1=2 # at 587 #151211 15:07:20 server id 72 end_log_pos 618 CRC32 0x9b35600a Xid = 6915 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@mysql5.6.12 binlog_new]# 

確實可以看到sql語句,不過都是row模式的,如下所示:

### INSERT INTO `test`.`z4` ### SET ### @1=2 # at 587

看到不到應用程序或者客戶端執行的真正sql語句,這樣也不利於進行業務分析數據分析,無助於對程序的優化。


5,問題分析

這樣binlog日志格式MIXED都錄制為亂碼,那我將換成STATEMENT格式看看是否會持續亂碼?,修改完my.cnf后,重啟mysql數據庫,開始建表測試,但是報錯如下:

mysql> create table z3 select 1 as a; ERROR 1665 (HY000): Cannot execute statement: impossible to write to binary log since BINLOG_FORMAT = STATEMENT and at least one table uses a storage engine limited to row-based logging. InnoDB is limited to row-logging when transaction isolation level is READ COMMITTED or READ UNCOMMITTED. mysql> 

問題發現了,看到問題賀新郎,隔離級別太低了,我的默認隔離級別是READ-COMMITTED,所以導致binlog記錄的必須都是row模式,解析出來的是亂碼,強行用-v顯示出來也是row模式,所以我將隔離級別升級為REPEATABLE-READ的話,就會有row格式也會有statement格式了。接下來為了用2個小實例來驗證我的判斷:


4.1 REPEATABLE-READ和STATEMENT測試結果

**所以我將隔離級別升級為REPEATABLE-READ,binlog設置為binlog_format=STATEMENT 
如下所示:**

# Set the default transaction isolation level. Levels available are: # READ-UNCOMMITTED, READ-COMMITTED, REPEATABLE-READ, SERIALIZABLE transaction_isolation = REPEATABLE-READ binlog_format=STATEMENT

然后重啟mysql,看binlog的記錄形式是啥樣的,如下所示:

BEGIN /*!*/; # at 219 # at 251 #151211 16:15:02 server id 72 end_log_pos 251 CRC32 0x4ea440db Intvar SET INSERT_ID=10550/*!*/; #151211 16:15:02 server id 72 end_log_pos 435 CRC32 0xa37c5f2d Query thread_id=1 exec_time=0 error_code=0 use `parking_db`/*!*/; SET TIMESTAMP=1449821702/*!*/; INSERT INTO access_log.access_log VALUES(NULL,CONNECTION_ID(),NOW(),USER(),CURRENT_USER()) /*!*/; # at 435 #151211 16:15:02 server id 72 end_log_pos 466 CRC32 0x2970e89a Xid = 3 COMMIT/*!*/; # at 466 #151211 16:16:22 server id 72 end_log_pos 569 CRC32 0xbe43b367 Query thread_id=2 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449821782/*!*/; create table z4 select 1 as a /*!*/; # at 569 #151211 16:16:32 server id 72 end_log_pos 648 CRC32 0x69b2383c Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1449821792/*!*/; BEGIN /*!*/; # at 648 #151211 16:16:32 server id 72 end_log_pos 745 CRC32 0xcd1721a4 Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1449821792/*!*/; insert into z4 select 2 /*!*/; # at 745 #151211 16:16:32 server id 72 end_log_pos 776 CRC32 0xfc0dcfc4 Xid = 70 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@mysql5.6.12 binlog_new]# 

看到有類似的INSERT INTO access_log.access_log VALUES(NULL,CONNECTION_ID(),NOW(),USER(),CURRENT_USER())這里的一些函數最好用row模式,因為主從復制的時候,uuid已經now()等會造成時間延遲,故而為了數據一致性,statement格式不是最佳選擇。


4.2 REPEATABLE-READ和MIXED測試結果

my.cnf里面修改設置:

transaction_isolation = REPEATABLE-READ binlog_format=MIXED

重啟mysql數據庫后,錄入測試數據:

mysql> insert into z4 select 3; Query OK, 1 row affected (0.00 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> exit

查看binlog數據,會看到insert into z4 select 3這條sql記錄,表明在mixed模式下,解析出來的sql是正常的,有些now()已經uuid的直接解析成row格式了,如下所示:

[root@mysql5.6.12 binlog_new]# /usr/local/mysql/bin/mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000007 ... # at 274 #151211 16:21:02 server id 72 end_log_pos 368 CRC32 0x156a1c51 Write_rows: table id 70 flags: STMT_END_F ### INSERT INTO `access_log`.`access_log` ### SET ### @1=10551 ### @2=1 ### @3=1449822062 ### @4='park_user@192.168.121.243' ### @5='park_user@192.168.%' # at 368 #151211 16:21:02 server id 72 end_log_pos 399 CRC32 0x8254defe Xid = 3 COMMIT/*!*/; # at 399 #151211 16:21:25 server id 72 end_log_pos 478 CRC32 0xe252f5c7 Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1449822085/*!*/; BEGIN /*!*/; # at 478 #151211 16:21:25 server id 72 end_log_pos 575 CRC32 0x34308ad6 Query thread_id=2 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449822085/*!*/; insert into z4 select 3 /*!*/; # at 575 #151211 16:21:25 server id 72 end_log_pos 606 CRC32 0x67c460eb Xid = 61 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@mysql5.6.12 binlog_new]# 


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM