zoukankan      html  css  js  c++  java
  • 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]# 
  • 相关阅读:
    好用的视频播放器
    如何屏蔽weGame今日推荐窗口
    存一个大佬的地图编辑器
    过渡页面,加载进度
    Lua中正弦,余弦函数的使用
    如何替换loadingBar的底图
    使用精灵帧缓存替换纹理
    setTexture和loadTexture之间的区别
    我胡汉三又回来了
    python中单斜杆和双斜杠的区别
  • 原文地址:https://www.cnblogs.com/duanxz/p/6651024.html
Copyright © 2011-2022 走看看