TQ's Notes Take notes, Reading...

MySQL二进制日志（binlog）

2016-06-02
TanQuan
MySQL
   

二进制日志（binary log）记录了对MySQL数据库执行更改的所有操作，但是不包括SELECT和SHOW这类操作，因为这类操作对数据本身并没有修改。然而，若操作本身并没有导致数据发生变化，那么该操作可能也会写入二进制日志。例如：

tqdb@localhost.[tqdb] 16:00:48> update t set b = 'dbtan' where a = 6;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 0  Changed: 0  Warnings: 0

tqdb@localhost.[tqdb] 16:01:06> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000129
         Position: 530
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)

tqdb@localhost.[tqdb] 16:01:22> show binlog events in 'mysql-bin.000129' \G
*************************** 1. row ***************************
   Log_name: mysql-bin.000129
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 120
       Info: Server ver: 5.6.25-enterprise-commercial-advanced-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: mysql-bin.000129
        Pos: 120
 Event_type: Query
  Server_id: 1
End_log_pos: 192
       Info: BEGIN
*************************** 3. row ***************************
   Log_name: mysql-bin.000129
        Pos: 192
 Event_type: Table_map
  Server_id: 1
End_log_pos: 239
       Info: table_id: 70 (tqdb.t)
*************************** 4. row ***************************
   Log_name: mysql-bin.000129
        Pos: 239
 Event_type: Update_rows
  Server_id: 1
End_log_pos: 294
       Info: table_id: 70 flags: STMT_END_F
*************************** 5. row ***************************
   Log_name: mysql-bin.000129
        Pos: 294
 Event_type: Xid
  Server_id: 1
End_log_pos: 325
       Info: COMMIT /* xid=6 */
*************************** 6. row ***************************
   Log_name: mysql-bin.000129
        Pos: 325
 Event_type: Query
  Server_id: 1
End_log_pos: 397
       Info: BEGIN
*************************** 7. row ***************************
   Log_name: mysql-bin.000129
        Pos: 397
 Event_type: Table_map
  Server_id: 1
End_log_pos: 444
       Info: table_id: 70 (tqdb.t)
*************************** 8. row ***************************
   Log_name: mysql-bin.000129
        Pos: 444
 Event_type: Update_rows
  Server_id: 1
End_log_pos: 499
       Info: table_id: 70 flags: STMT_END_F
*************************** 9. row ***************************
   Log_name: mysql-bin.000129
        Pos: 499
 Event_type: Xid
  Server_id: 1
End_log_pos: 530
       Info: COMMIT /* xid=8 */
9 rows in set (0.00 sec)

从上述例子中可以看到，MySQL数据库首先进行UPDATE操作，从返回的结果看到Changed: 0，这意味着该操作并没有导致数据的变化。但是通过SHOW BINLOG EVENTS可以看出二进制日志中的确进行了记录。

如果用户想记录SELECT和SHOW操作，那只能使用查询日志，而不是二进制日志。此外，二进制日志还包括了执行数据库更改操作的时间等其他额外信息。总的来说，二进制日志主要有以下几种作用：

  • 恢复（recovery）：某些数据的恢复需要二进制日志。例如，在一个数据库全备文件恢复后，用户可以通过二进制日志进行point-in-time的恢复。
  • 复制（replication）：其原理与恢复类似，通过复制和执行二进制日志使一台远程的MySQL数据库（一般称为slave或者standby）与一台MySQL数据库（一般称为master或者primary）进行实时同步。
  • 审计（audit）：用户可以通过二进制日志中的信息来进行审计，判断是否有对数据库进行注入攻击。

通过配置参数log-bin [=name]可以启动二进制日志。如果不指定name，则默认二进制日志文件名为主机名，后缀名为二进制日志的序列号，所在目录为数据库所在目录（datadir），如：

tqdb@localhost.[tqdb] 16:24:33> show variables like 'datadir';
+---------------+--------------+
| Variable_name | Value        |
+---------------+--------------+
| datadir       | /MySQL_DATA/ |
+---------------+--------------+
1 row in set (0.00 sec)

tqdb@localhost.[tqdb] 16:24:52> system ls -lh /MySQL_DATA
total 5.6G
drwx------ 2 mysql mysql 4.0K Jul  9  2015 abc
-rw-rw---- 1 mysql mysql   56 Jul  8  2015 auto.cnf
-rw-rw---- 1 mysql mysql 1.0G May 12 16:00 ibdata1
-rw-rw---- 1 mysql mysql 256M May 12 16:00 ib_logfile0
-rw-rw---- 1 mysql mysql 256M May 11 19:19 ib_logfile1
-rw-rw---- 1 mysql mysql 256M May 11 19:20 ib_logfile2
drwx------ 2 mysql mysql 4.0K May  3 17:24 mysql
-rw-rw---- 1 mysql mysql 467M Apr 19 08:47 mysql-bin.000122
-rw-rw---- 1 mysql mysql 1.1G Apr 26 18:05 mysql-bin.000123
-rw-rw---- 1 mysql mysql  120 Apr 26 18:34 mysql-bin.000124
-rw-rw---- 1 mysql mysql  863 May  3 18:01 mysql-bin.000125
-rw-rw---- 1 mysql mysql 1.9G May  9 15:04 mysql-bin.000126
-rw-rw---- 1 mysql mysql  737 May 11 16:29 mysql-bin.000127
-rw-rw---- 1 mysql mysql 422M May 12 14:06 mysql-bin.000128
-rw-rw---- 1 mysql mysql  530 May 12 16:00 mysql-bin.000129
-rw-rw---- 1 mysql mysql  152 May 12 14:06 mysql-bin.index
srwxrwxrwx 1 mysql mysql    0 May 12 14:06 mysql.sock
drwx------ 2 mysql mysql 4.0K Nov 20 17:30 new_apply_1113
drwx------ 2 mysql mysql 4.0K Apr 26 18:02 new_apply_online
drwx------ 2 mysql mysql 4.0K Jul  8  2015 performance_schema
drwx------ 2 mysql mysql 4.0K May  5 18:27 sakila
drwx------ 2 mysql mysql 4.0K Apr 15 17:27 scene
drwxr-xr-x 2 mysql mysql 4.0K Jan 20 18:28 test
-rw-r----- 1 mysql mysql  22K May 12 14:06 test-178.err
-rw-rw---- 1 mysql mysql    1 Apr 26 18:15 test-178.log
-rw-rw---- 1 mysql mysql    5 May 12 14:06 test-178.pid
-rw-rw---- 1 mysql mysql 5.9K May 12 14:06 test-178-slow.log
drwx------ 2 mysql mysql 4.0K May 11 19:07 tqdb
drwx------ 2 mysql mysql 4.0K Apr 21 13:59 wxmall
tqdb@localhost.[tqdb] 16:25:47> system cat /etc/my.cnf | grep log-bin
log-bin=mysql-bin

这里的mysql-bin.000122即为二进制文件，我们在配置文件指定了名字，所以没有用默认的文件名。mysql-bin.index为二进制日志的索引文件，用来存储过往产生的二进制日志序号，在通常情况下，不建议手工修改这个文件。

二进制日志文件在默认情况下并没有启动，需要手动指定参数来启动。可能有人会质疑，开启这个选项是否会对数据库整体性能有所影响。不错，开启这个选项的确会影响性能，但是性能的损失十分有限。根据MySQL官方手册中的测试表明，开启二进制日志会使性能下降1％。但考虑到可以使用复制（replication）和point-in-time的恢复，这些性能损失绝对是可以且应该被接受的。

以下配置文件的参数影响着二进制日志记录的信息会行为：

  • max_binlog_size
  • binlog_cache_size
  • sync_binlog
  • binlog-do-db
  • binlog-ignore-db
  • log-slave-update
  • binlog-format

参数max_binlog_size指定了单个二进制日志文件的最的值，如果超过该值，则产生新的二进制文件，后缀名+1，并记录到.index文件。从MySQL 5.0 开始的默认值为1073741824，代表1G（在之前的版本中max_binlog_size默认大小为1.1G）。

当使用事务的表存储引擎（如InnoDB存储引擎）时，所有未提交（uncommitted）的二进制日志会被记录到一个缓存中去，等该事务提交（committed）时直接将缓冲中的二进制日志写入二进制日志文件，而该缓冲的大小由binlog_cache_size决定，默认大小为32K。此外，binlog_cache_size是基于会话（session）的，也就是说，当一个线程开始一个事务时，MySQL会自动分配一个大小为binlog_cache_size的缓存，因此该值的设置需要相当小心，不能设置过大。当一个事务的记录大于设定的binlog_cache_size时，MySQL会把缓冲中的日志写入一个临时文件中，因此该值又不能设得太小。通过SHOW GLOBAL STATUS命令查看binlog_cache_use、binlog_cache_disk_use的状态，可以判断当前binlog_cache_size的设置是否合适。binlog_cache_use记录了使用缓冲写二进制日志的次数，binlog_cache_disk_use记录了使用临时文件写二进制日志的次数。现在来看一个数据的状态：

tqdb@localhost.[tqdb] 14:45:26> show variables like 'binlog_cache_size%';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| binlog_cache_size | 32768 |
+-------------------+-------+
1 row in set (0.01 sec)

tqdb@localhost.[tqdb] 14:45:57> show global status like 'binlog_cache%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Binlog_cache_disk_use | 999   |
| Binlog_cache_use      | 2997  |
+-----------------------+-------+
2 rows in set (0.00 sec)

使用缓冲次数为2997，临时文件使用次数为999。是由于我们之前在这个测试库里对一个有1300W＋的大表进行过多次大数据量的操作。例如：update

tqdb@localhost.[tqdb] 14:57:10> select count(*) from test_table;
+----------+
| count(*) |
+----------+
| 13930919 |
+----------+
1 row in set (6.71 sec)

tqdb@localhost.[tqdb] 14:58:08> update test_table set path = '/dbtan';
Query OK, 13930919 rows affected (4 min 0.47 sec)
Rows matched: 13930919  Changed: 13930919  Warnings: 0

-- 再来看，使用缓冲次数、临时文件使用次数都增长（+1）了。
tqdb@localhost.[tqdb] 14:56:52> show global status like 'binlog_cache%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Binlog_cache_disk_use | 1000  |
| Binlog_cache_use      | 2998  |
+-----------------------+-------+
2 rows in set (0.02 sec)

在默认情况下，二进制日志并不是在每次写的时候同步的磁盘（用户可以理解为缓冲写）。因此，当数据库所在的操作系统发生宕机时，可能会有最后一部分数据没有写入二进制文件中，这会给恢复和复制带来问题。参数sync_binlog=[N]表示每写缓冲多少次就同步到磁盘。如果将N设为1，即sync_binlog=1表示采用同步写磁盘的方式来写二进制日志，这时写操作不使用操作系统的缓冲来写二进制日志。sync_binlog的默认值为0，如果使用Innodb存储引擎进行复制，并且想得到最大的高可用性，建议将该值设为ON。不过该值为ON时，确时会对数据库IO系统带来一定的影响。

但是，即使将sync_binlog设为1，还是会有一种情况导致问题的发生。当使用InnoDB存储引擎时，在一个事务发出COMMIT动作之前，由于sync_binlog为1，因此会将二进制日志立即写入磁盘。如果这时已经写入了二进制日志，但是提交还没有发生，并且此时发生了宕机，那么在MySQL数据库下次启动时，由于COMMIT操作并没有发生，这个事务会被回滚掉。但是二进制日志已经记录了该事务信息，不能被回滚。这个问题可以通过将参数innodb_support_xa设置为1来解决，虽然innodb_support_xa与XA事务有关，但它同时也确保了二进制日志和InnoDB存储引擎数据文件的同步。

参数binlog-do-db和binlog-ignore-db表示需要写入或者忽略写入哪些库的日志。默认为空，表示需要同步所有库的日志到二进制日志。

如果当前数据库是复制中的slave角色，则它不会将master取得并执行的二进制日志写入自己的二进制日志文件中去。如果需要写入，要设置log-slave-update。如果需要搭建master-->slave-->slave架构的复制，则必须设置该参数。

binlog_format参数十分重要，它影响了记录二进制日志的格式。在MySQL 5.1版本之前，没有这个参数。所有二进制文件的格式都是基于SQL语句（statement）级别的，因此基于这个格式的二进制日志文件的复制（Replication）和Oracle的逻辑Standby有点相似。同时，对于复制是有一定要求的。如在主服务器运行rand、uuid等函数，又或者使用触发器等操作，这些都可能会导致主从服务器上表中数据不一致（not sync）。另一个影响是，会发现InnoDB存储引擎的默认事务隔离级别是REPEATABLE READ。这其实也是因为二进制日志文件格式的关系，如果使用READ COMMITTED的事务隔离级别（大多数数据库，如Oracle，Microsoft SQL Server数据库的默认事务隔离级别），会出现类似丢失更新的现象，从而出现主从数据库上的数据不一致。

MySQL 5.1开始引入了binlog_format参数，该参数可设的值有STATEMENT、ROW和MIXED。

  1. STATEMENT格式和之前的MySQL版本一样，二进制日志文件记录的是日志的逻辑SQL语句。
  2. 在ROW格式下，二进制日志记录的不再是简单的SQL语句了，而是记录表的行更改情况。基于ROW格式的复制类似于Oracle的物理Standby（当然，还是有些区别）。同时，对上述提及的STATEMENT格式下复制的问题予以解决。从MySQL 5.1版本开始，如果设置了binlog_format为ROW，可以将InnoDB的事务隔离级别设为READ COMMITTED，以获得更好的并发行。
  3. 在MIXED格式下，MySQL默认采用STATEMENT格式进行二进制日志文件的记录，但是在一些情况下会使用ROW格式，可能的情况有：
    1. 表的存储引擎为NDB，这时对表的DML操作都会以ROW格式记录。
    2. 使用了UUID()、USER()、CURRENT_USER()、FOUND_ROW()、ROW_COUNT()等不确定函数。
    3. 使用了INSERT DELAY语句。
    4. 使用了用户定义函数（UDF）。
    5. 使用了临时表（temporary table）。

binlog_format是动态参数，因此可以在数据库运行环境下进行更改，例如我们可以将当前会话的binlog_format设为ROW，如：

tqdb@localhost.[tqdb] 17:43:46> set @@session.binlog_format='ROW';
Query OK, 0 rows affected (0.00 sec)

tqdb@localhost.[tqdb] 17:44:10> select @@session.binlog_format;
+-------------------------+
| @@session.binlog_format |
+-------------------------+
| ROW                     |
+-------------------------+
1 row in set (0.00 sec)

当然，也可以将全局的binlog_format设置为想要的格式，不过通常这个操作会带来问题，运行时要确保更改后不会对复制带来影响。如：

tqdb@localhost.[tqdb] 17:48:50> set global binlog_format = 'ROW';
Query OK, 0 rows affected (0.00 sec)

tqdb@localhost.[tqdb] 17:49:37> select @@global.binlog_format;
+------------------------+
| @@global.binlog_format |
+------------------------+
| ROW                    |
+------------------------+
1 row in set (0.00 sec)

在通常情况下，我们将参数binlog_format设置为ROW，这可以为数据库的恢复和复制带来更好的可靠性。但是不能忽略的一点是，这会带来二进制文件大小的增加，有些语句下的ROW格式可能需要更大的容量。比如我们有两张一样的表，大小都为100W，分别UPDATE操作，观察二进制日志大小的变化：

tqdb@localhost.[tqdb] 19:09:02> set @@session.binlog_format = 'STATEMENT';
Query OK, 0 rows affected (0.00 sec)

tqdb@localhost.[tqdb] 19:10:44> select @@session.binlog_format;
+-------------------------+
| @@session.binlog_format |
+-------------------------+
| STATEMENT               |
+-------------------------+
1 row in set (0.00 sec)

tqdb@localhost.[tqdb] 19:10:48> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000128
         Position: 112702410
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)

tqdb@localhost.[tqdb] 19:10:51> update test1 set path = '/tq';
Query OK, 1000000 rows affected (14.92 sec)
Rows matched: 1000000  Changed: 1000000  Warnings: 0

tqdb@localhost.[tqdb] 19:12:04> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000128
         Position: 112702623
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)

可以看到，在binlog_format格式为STATEMENT的情况下，执行UPDATE语句后二进制日志大小中增加了213字节（112702623 - 112702410）。如果是使用ROW格式，同样对test2表进行操作，可以看到：

tqdb@localhost.[tqdb] 19:19:19> set @@session.binlog_format = 'ROW';
Query OK, 0 rows affected (0.00 sec)

tqdb@localhost.[tqdb] 19:19:30> select @@session.binlog_format;
+-------------------------+
| @@session.binlog_format |
+-------------------------+
| ROW                     |
+-------------------------+
1 row in set (0.00 sec)

tqdb@localhost.[tqdb] 19:19:35> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000128
         Position: 332108535
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)

tqdb@localhost.[tqdb] 19:19:40> update test2 set path = '/tq';
Query OK, 1000000 rows affected (18.30 sec)
Rows matched: 1000000  Changed: 1000000  Warnings: 0

tqdb@localhost.[tqdb] 19:20:09> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000128
         Position: 441811491
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)

[mysql@test-178: /MySQL_DATA/tqdb]$ ll -th test*
-rw-rw---- 1 mysql mysql  92M May 11 19:20 test2.ibd
-rw-rw---- 1 mysql mysql  92M May 11 19:12 test1.ibd
-rw-rw---- 1 mysql mysql 8.8K May 11 19:07 test2.frm
-rw-rw---- 1 mysql mysql 8.8K May 11 19:06 test1.frm

这时会惊讶地发现，同样的操作在ROW格式下竟然需要109702956字节（441811491 - 332108535），二进制日志文件的大小差不多增加了100MB，要知道test2表的大小也不超过92MB。而且执行时间也有所增加（这里我设置了sync_binlog=1）。这是因为这时MySQL数据库不再将逻辑的SQL操作记录到二进制日志中，而是记录对于每行的更改。

上面的这个例子告诉我们，将参数binlog_format设置为ROW，会对磁盘空间要求有一定的增加。而由于复制是传输二进制日志方式实现的，因此复制的网络开销也有所增加。

二进制日志文件的文件格式为二进制（好像有点废话），不能像错误日志文件、慢查询日志文件那样用cat、head、tail等命令来查看。要查看二进制日志文件的内容，必须通过MySQL提供的工具mysqlbinlog。对于STATEMENT格式的二进制文件，在使用mysqlbinlog后，看到的就是执行的逻辑SQL语加，如：

[mysql@test-178: /MySQL_DATA]$ mysqlbinlog --no-defaults --start-position=112702410 mysql-bin.000128 | less
/*!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
#160511 16:29:49 server id 1  end_log_pos 120 CRC32 0x5bf6b7d8  Start: binlog v 4, server v 5.6.25-enterprise-commercial-advanced-log created 160511 16:29:49 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
fe0yVw8BAAAAdAAAAHgAAAABAAQANS42LjI1LWVudGVycHJpc2UtY29tbWVyY2lhbC1hZHZhbmNl
ZC1sb2cAAAAAAAAAAAB97TJXEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAdi3
9ls=
'/*!*/;
# at 112702410
#160511 19:11:49 server id 1  end_log_pos 112702489 CRC32 0x1f67544f    Query   thread_id=1     exec_time=15    error_code=0
SET TIMESTAMP=1462965109/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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 112702489
#160511 19:11:49 server id 1  end_log_pos 112702592 CRC32 0x90bb1964    Query   thread_id=1     exec_time=15    error_code=0
use `tqdb`/*!*/;
SET TIMESTAMP=1462965109/*!*/;
update test1 set path = '/tq'
/*!*/;
# at 112702592
#160511 19:11:49 server id 1  end_log_pos 112702623 CRC32 0x22fb745f    Xid = 42
COMMIT/*!*/;
# at 112702623
#160511 19:16:41 server id 1  end_log_pos 112702695 CRC32 0x0a1b10d4    Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1462965401/*!*/;

通过SQL语句update test1 set path = '/tq'可以看到，二进制日志的记录采用SQL语句的方式。在这种情况下，mysqlbinlog和Oracle LogMiner类似。但是如果这时使用ROW格式的记录方式，会发现mysqlbinlog的结果变得“不可读”（unreadable），如：

[mysql@test-178: /MySQL_DATA]$ mysqlbinlog --no-defaults --start-position=332108535 mysql-bin.000128 | less
/*!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
#160511 16:29:49 server id 1  end_log_pos 120 CRC32 0x5bf6b7d8  Start: binlog v 4, server v 5.6.25-enterprise-commercial-advanced-log created 160511 16:29:49 at startup
ROLLBACK/*!*/;
BINLOG '
fe0yVw8BAAAAdAAAAHgAAAAAAAQANS42LjI1LWVudGVycHJpc2UtY29tbWVyY2lhbC1hZHZhbmNl
ZC1sb2cAAAAAAAAAAAB97TJXEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAdi3
9ls=
'/*!*/;
# at 332108535
#160511 19:19:51 server id 1  end_log_pos 332108607 CRC32 0xcb9dd533    Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1462965591/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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 332108607
#160511 19:19:51 server id 1  end_log_pos 332108672 CRC32 0x6a6188a5    Table_map: `tqdb`.`test2` mapped to number 73
# at 332108672
#160511 19:19:51 server id 1  end_log_pos 332116833 CRC32 0x92c6353e    Update_rows: table id 73
# at 332116833
#160511 19:19:51 server id 1  end_log_pos 332124909 CRC32 0xee6c81de    Update_rows: table id 73
# at 332124909
#160511 19:19:51 server id 1  end_log_pos 332133112 CRC32 0xc0eef064    Update_rows: table id 73
# at 332133112
#160511 19:19:51 server id 1  end_log_pos 332141289 CRC32 0x5cba6ee7    Update_rows: table id 73
# at 332141289
#160511 19:19:51 server id 1  end_log_pos 332149381 CRC32 0xca1760fa    Update_rows: table id 73
# at 332149381
...skipping...
ADE0MDEyNTUxNzE3NTEuanBngABcJpmS+AAAmZeVZcoAPUIPAJMZAQABMwMvdHERADE0MDEyNTUx
NzE3NTEuanBngABcJpmS+AAAmZeVZcoAPkIPAJMZAQABMwYvZGJ0YW4RADE0MDEyNTUxNzUzNzcu
anBngABcPJmS+AAAmZeVZcoAPkIPAJMZAQABMwMvdHERADE0MDEyNTUxNzUzNzcuanBngABcPJmS
+AAAmZeVZcoAP0IPAJMZAQABMwYvZGJ0YW4RADE0MDEyNTUxNzU5NzYuanBngABZMpmS+AAAmZeV
ZcoAP0IPAJMZAQABMwMvdHERADE0MDEyNTUxNzU5NzYuanBngABZMpmS+AAAmZeVZcoAQEIPAJMZ
AQABMwYvZGJ0YW4RADE0MDEyNTUxNzY1OTYuanBngABZNZmS+AAAmZeVZcoAQEIPAJMZAQABMwMv
dHERADE0MDEyNTUxNzY1OTYuanBngABZNZmS+AAAmZeVZcpkZMax
'/*!*/;
# at 441811460
#160511 19:19:51 server id 1  end_log_pos 441811491 CRC32 0x694b3b81    Xid = 59
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

这里看不到执行的SQL语句，反而是一大串用户不可读的字符。其实只要加上参数-v或者-vv就能清楚地看到执行的具体信息了。-vv会比-v多显示出更新的类型。加上-vv选项，可以得到：

[mysql@test-178: /MySQL_DATA]$ mysqlbinlog --no-defaults -vv --start-position=332108535 mysql-bin.000128 | less
/*!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
#160511 16:29:49 server id 1  end_log_pos 120 CRC32 0x5bf6b7d8  Start: binlog v 4, server v 5.6.25-enterprise-commercial-advanced-log created 160511 16:29:49 at startup
ROLLBACK/*!*/;
BINLOG '
fe0yVw8BAAAAdAAAAHgAAAAAAAQANS42LjI1LWVudGVycHJpc2UtY29tbWVyY2lhbC1hZHZhbmNl
ZC1sb2cAAAAAAAAAAAB97TJXEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAdi3
9ls=
'/*!*/;
# at 332108535
#160511 19:19:51 server id 1  end_log_pos 332108607 CRC32 0xcb9dd533    Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1462965591/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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 332108607
#160511 19:19:51 server id 1  end_log_pos 332108672 CRC32 0x6a6188a5    Table_map: `tqdb`.`test2` mapped to number 73
# at 332108672
#160511 19:19:51 server id 1  end_log_pos 332116833 CRC32 0x92c6353e    Update_rows: table id 73
# at 332116833
#160511 19:19:51 server id 1  end_log_pos 332124909 CRC32 0xee6c81de    Update_rows: table id 73
# at 332124909
#160511 19:19:51 server id 1  end_log_pos 332133112 CRC32 0xc0eef064    Update_rows: table id 73
# at 332133112
#160511 19:19:51 server id 1  end_log_pos 332141289 CRC32 0x5cba6ee7    Update_rows: table id 73
# at 332141289
#160511 19:19:51 server id 1  end_log_pos 332149381 CRC32 0xca1760fa    Update_rows: table id 73
# at 332149381
...skipping...
### UPDATE `tqdb`.`test2`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=0 is_null=0 */
###   @3='4' /* VARSTRING(8) meta=8 nullable=0 is_null=0 */
###   @4='/dbtan' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='bd843399-8368-4185-805b-20177afb086c.png' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @6=56.66 /* DECIMAL(7,2) meta=1794 nullable=1 is_null=0 */
###   @7='2012-02-28 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=0 is_null=0 */
###   @3='4' /* VARSTRING(8) meta=8 nullable=0 is_null=0 */
###   @4='/tq' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='bd843399-8368-4185-805b-20177afb086c.png' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @6=56.66 /* DECIMAL(7,2) meta=1794 nullable=1 is_null=0 */
###   @7='2012-02-28 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### UPDATE `tqdb`.`test2`
### WHERE
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=0 is_null=0 */
###   @3='10' /* VARSTRING(8) meta=8 nullable=0 is_null=0 */
###   @4='/dbtan' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='e72656c4-d1b6-4af2-b61c-b40803a56213.png' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @6=56.66 /* DECIMAL(7,2) meta=1794 nullable=1 is_null=0 */
###   @7='2012-02-28 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=0 is_null=0 */
###   @3='10' /* VARSTRING(8) meta=8 nullable=0 is_null=0 */
###   @4='/tq' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='e72656c4-d1b6-4af2-b61c-b40803a56213.png' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @6=56.66 /* DECIMAL(7,2) meta=1794 nullable=1 is_null=0 */
###   @7='2012-02-28 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### UPDATE `tqdb`.`test2`
...skipping...
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### UPDATE `tqdb`.`test2`
### WHERE
###   @1=1000000 /* INT meta=0 nullable=0 is_null=0 */
###   @2=72083 /* INT meta=0 nullable=0 is_null=0 */
###   @3='3' /* VARSTRING(8) meta=8 nullable=0 is_null=0 */
###   @4='/dbtan' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='1401255176596.jpg' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @6=89.53 /* DECIMAL(7,2) meta=1794 nullable=1 is_null=0 */
###   @7='2014-05-28 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
###   @1=1000000 /* INT meta=0 nullable=0 is_null=0 */
###   @2=72083 /* INT meta=0 nullable=0 is_null=0 */
###   @3='3' /* VARSTRING(8) meta=8 nullable=0 is_null=0 */
###   @4='/tq' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='1401255176596.jpg' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @6=89.53 /* DECIMAL(7,2) meta=1794 nullable=1 is_null=0 */
###   @7='2014-05-28 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
###   @8='2015-11-10 22:23:10' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 441811460
#160511 19:19:51 server id 1  end_log_pos 441811491 CRC32 0x694b3b81    Xid = 59
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

现在mysqlbinlog向我们解释了它具体做的事情。可以看到，一条简单的update test2 set path = '/tq'语句记录了对于整个行更改的信息，这也解释了为什么前面更新了100W行的数据，在ROW格式下，二进制日志文件会增加100MB。

– The End –

Similar Posts

上一篇 MySQL InnoDB锁和死锁

下一篇 一个客户端设置多个github账号

Comments

Content