手动创建binary log files和手动编辑binary log index file会有什么影响

Posted 醒嘞

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了手动创建binary log files和手动编辑binary log index file会有什么影响相关的知识，希望对你有一定的参考价值。

基本环境：官方社区版mysql 5.7.19

一、了解Binary Log结构

1.1、High-Level Binary Log Structure and Contents

• Binlog包括binary log files和index file
• 每个binary log文件的前4字节是Magic Number，紧接着是一组描述数据修改的Events
　　• The magic number bytes are 0xfe 0x62 0x69 0x6e = 0xfe \'b\'\'i\'\'n\'
　　• 每个Event包括header bytes和data bytes
　　　　header bytes：Event类型，什么时候，由哪个server生成等信息
　　　　data bytes：特定的数据修改
　　• 第一个Event是Description Event，描述文件的格式版本
　　• 其他Events按照binlog_version(1、3、4)进行记录
　　• 最后一个Event是Log-rotation Event，指定下一个binary log的文件名称
• index文件里面是当前binary log的一个列表

1.2、Binary Log结构示意图

# Binary Log结构示意图(binlog_version=4)
               |<----------------------------------Events---------------------------------->|
               |<---------Fisrt Event--------->|<------Mid Events----->|<---Final Event---->|
+--------------+-------------------------------+--------+-----+--------+--------------------+
| Magic Number | FDE(Format Description Event) | Event1 | ... | EventN | Log-rotation Event |
+--------------+-------------------------------+--------+-----+--------+--------------------+
               |<-event header->|<-event data->|
View Code


上图是binlog_version=4(MySQL 5.0 and up)的示意图

二、index file添加一行不存在的binary log记录

查看当前binary log

# 查看当前binary log
[root@ZST1 logs]# ll
total 20
-rw-r-----. 1 mysql mysql 201 Jan 12 11:32 mysql-bin.000004
-rw-r-----. 1 mysql mysql 201 Jan 12 11:32 mysql-bin.000005
-rw-r-----. 1 mysql mysql 177 Jan 12 11:34 mysql-bin.000006
-rw-r-----. 1 mysql mysql 177 Jan 12 11:37 mysql-bin.000007
-rw-r-----. 1 mysql mysql 220 Jan 12 11:34 mysql-bin.index
[root@ZST1 logs]# cat mysql-bin.index 
/data/mysql/mysql3308/logs/mysql-bin.000004
/data/mysql/mysql3308/logs/mysql-bin.000005
/data/mysql/mysql3308/logs/mysql-bin.000006
/data/mysql/mysql3308/logs/mysql-bin.000007
[root@ZST1 logs]#
View Code

mysql-bin.index 添加一行已经删除的记录/data/mysql/mysql3308/logs/mysql-bin.000001，重新启动数据库服务

# 查看error log
[root@ZST1 ~]# more /data/mysql/mysql3308/data/error.log
...
2018-01-12T03:34:33.467474Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3308/data/ib_buffer_pool
mysqld: File \'/data/mysql/mysql3308/logs/mysql-bin.000001\' not found (Errcode: 2 - No such file or directory)
2018-01-12T03:34:33.546276Z 0 [ERROR] Failed to open log (file \'/data/mysql/mysql3308/logs/mysql-bin.000001\', errno 2)
2018-01-12T03:34:33.546294Z 0 [ERROR] Could not open log file
2018-01-12T03:34:33.563485Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2018-01-12T03:34:33.563528Z 0 [Note] Server hostname (bind-address): \'*\'; port: 3308
数据库服务最终启动起来
View Code

mysql-bin.index 添加一行未来的记录/data/mysql/mysql3308/logs/mysql-bin.000017，重新启动数据库服务

# 查看error log
[root@ZST1 ~]# more /data/mysql/mysql3308/data/error.log
...
2018-01-12T03:44:45.921370Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3308/data/ib_buffer_pool
mysqld: File \'/data/mysql/mysql3308/logs/mysql-bin.000017\' not found (Errcode: 2 - No such file or directory)
2018-01-12T03:44:46.017490Z 0 [ERROR] Failed to open log (file \'/data/mysql/mysql3308/logs/mysql-bin.000017\', errno 2)
2018-01-12T03:44:46.017509Z 0 [ERROR] Could not open log file
2018-01-12T03:44:46.017532Z 0 [ERROR] Can not init tc log
2018-01-12T03:44:46.017545Z 0 [ERROR] Aborting
数据库服务最终退出
View Code

启动过程会读取index file中的第一条和最后一条记录，然后检查对应的文件是否存在。如果第一条不存在，error log中会有报错，但服务正常启动；如果最后一条不存在，error log中会有报错，服务退出。即使你打乱index file中列表顺序，或者写入其他信息，它始终只验证index file的第一条和最后一条~

三、手动创建一个binary log，但不添加到index file

如果touch_seq < max(exists_seq)，正常启动，最新的new_seq=max(exists_seq)+1
如果max(exists_seq) < touch_seq < pow(2,31)-1，正常启动，最新的new_seq=touch_seq+1，当new_seq > pow(2,31)-1001 时会往error log中写入警告
如果touch_seq = pow(2,31)-1，mysqld退出
如果touch_seq > pow(2,31)-1，正常启动，会往error log中写入警告

3.1、MySQL binlog后面的编号最大是多大

最大编号参考文章：MySQL binlog后面的编号最大是多大

原文结论：
1、MySQL binlog的最大sequence是：pow(2,31)-1 = 2147483647
2、当 pow(2,31)-1001 < sequence < pow(2,31)-1 会往error log中写入警告
3、binlog的sequence达到最大值(2147483647)时，不管有没有mysql-bin.000001类似这样的文件，mysqld都是退出
4、在MySQL产生binlog时会读取当前日件文目录下的log-bin的base name获取下一个日志文件的后面的Seq。所以日志目录下文件太多，会影响MySQL的启动及日志切换。这里也有一个大的隐患，运行中给放一个较大的日志文件，在下次日志文件切换时有可能很快就接近于最大值，造成mysqld crash退出
5、一定要监控error log的输出，并足够重视

查看源码(5.7.19)

# 源码信息 sql/binlog.cc
#define MAX_LOG_UNIQUE_FN_EXT 0x7FFFFFFF
#define LOG_WARN_UNIQUE_FN_EXT_LEFT 1000

  /* check if reached the maximum possible extension number */
  if (max_found == MAX_LOG_UNIQUE_FN_EXT)
  {
    sql_print_error("Log filename extension number exhausted: %06lu. \\
Please fix this by archiving old logs and \\
updating the index files.", max_found);
    error= 1;
    goto end;
  }

  /* print warning if reaching the end of available extensions. */
  if ((next > (MAX_LOG_UNIQUE_FN_EXT - LOG_WARN_UNIQUE_FN_EXT_LEFT)))
    sql_print_warning("Next log extension: %lu. \\
Remaining log filename extensions: %lu. \\
Please consider archiving some logs.", next, (MAX_LOG_UNIQUE_FN_EXT - next));

mysql> select conv(\'7FFFFFFF\',16,10);
+------------------------+
| conv(\'7FFFFFFF\',16,10) |
+------------------------+
| 2147483647             |
+------------------------+
View Code

源码逻辑正是上面的结论1、2、3。如果我们的binlog的sequence疯涨到2147483647，那很不幸mysqld会退出。。。但如果我们在正常情况下，touch一个大于2147483647的binary log的文件会出现什么情况呢？

3.2、MySQL binlog后面的编号最大到底是多大

首先我们从2147483648开始

# reset master
mydba@192.168.85.132,3308 [replcrash]> reset master;
Query OK, 0 rows affected (0.01 sec)
# 查看binary log
mydba@192.168.85.132,3308 [replcrash]> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       154 |
+------------------+-----------+
row in set (0.00 sec)
# touch 2^31
[root@ZST1 logs]# touch mysql-bin.2147483648
[root@ZST1 logs]# chown -R mysql:mysql *
# flush执行5次
mydba@192.168.85.132,3308 [replcrash]> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
# 查看binary log
mydba@192.168.85.132,3308 [replcrash]> show binary logs;
+----------------------+-----------+
| Log_name             | File_size |
+----------------------+-----------+
| mysql-bin.000001     |       205 |
| mysql-bin.2147483649 |       205 |
| mysql-bin.2147483650 |       205 |
| mysql-bin.2147483651 |       205 |
| mysql-bin.2147483652 |       205 |
| mysql-bin.2147483653 |       154 |
+----------------------+-----------+
rows in set (0.00 sec)
# 查看error log
[root@ZST1 data]# cat error.log 
2018-01-08T09:09:06.235149Z 3 [Warning] Next log extension: 2147483649. Remaining log filename extensions: 18446744073709551614. Please consider archiving some logs.
2018-01-08T09:09:23.868883Z 3 [Warning] Next log extension: 2147483650. Remaining log filename extensions: 18446744073709551613. Please consider archiving some logs.
2018-01-08T09:10:29.670811Z 3 [Warning] Next log extension: 2147483651. Remaining log filename extensions: 18446744073709551612. Please consider archiving some logs.
2018-01-08T09:10:30.401541Z 3 [Warning] Next log extension: 2147483652. Remaining log filename extensions: 18446744073709551611. Please consider archiving some logs.
2018-01-08T09:10:31.075702Z 3 [Warning] Next log extension: 2147483653. Remaining log filename extensions: 18446744073709551610. Please consider archiving some logs.
[root@ZST1 logs]# 

# 再次reset master
mydba@192.168.85.132,3308 [replcrash]> reset master;
Query OK, 0 rows affected (0.02 sec)
# 查看binary log
mydba@192.168.85.132,3308 [replcrash]> show binary logs;
+----------------------+-----------+
| Log_name             | File_size |
+----------------------+-----------+
| mysql-bin.2147483649 |       154 |
+----------------------+-----------+
row in set (0.00 sec)
View Code

可以看到，执行flush binary logs后，sequence一直往后+1(next)。error log中会有警告日志，next > (MAX_LOG_UNIQUE_FN_EXT - LOG_WARN_UNIQUE_FN_EXT_LEFT)恒成立；Remaining log filename extensions后面的数值看着有点怪异~
第二次reset后的sequence从2147483649开始，并不是从000001开始，不知道什么原因。
我们继续加大sequence，直到接近9223372036854775808

# touch 2^63-2
[root@ZST1 logs]# touch mysql-bin.9223372036854775806
[root@ZST1 logs]# chown -R mysql:mysql *
# flush执行5次
mydba@192.168.85.132,3308 [replcrash]> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
# 查看binary log
mydba@192.168.85.132,3308 [replcrash]> show binary logs;
+-------------------------------+-----------+
| Log_name                      | File_size |
+-------------------------------+-----------+
| mysql-bin.000001              |       214 |
| mysql-bin.9223372036854775807 |       214 |
| mysql-bin.9223372036854775808 |       154 |
| mysql-bin.9223372036854775808 |       154 |
| mysql-bin.9223372036854775808 |       154 |
| mysql-bin.9223372036854775808 |       154 |
+-------------------------------+-----------+
rows in set (0.00 sec)
# 查看error log
[root@ZST1 data]# cat error.log 
2018-01-08T09:35:20.879612Z 3 [Warning] Next log extension: 9223372036854775807. Remaining log filename extensions: 9223372039002259456. Please consider archiving some logs.
2018-01-08T09:35:22.082530Z 3 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.
2018-01-08T09:35:22.934636Z 3 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.
2018-01-08T09:35:23.544604Z 3 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.
2018-01-08T09:35:24.134664Z 3 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.
[root@ZST1 logs]#
View Code

当sequence达到9223372036854775808后，再flush binary log，看不出产生新binary log~

[root@ZST1 logs]# mysqlbinlog -v --base64-output=decode-rows mysql-bin.9223372036854775808
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#180112 15:57:18 server id 1323308  end_log_pos 123 CRC32 0x798b200f    Start: binlog v 4, server v 5.7.19-log created 180112 15:57:18
# Warning: this binlog is either in use or was not closed properly.
# at 123
#180112 15:57:18 server id 1323308  end_log_pos 154 CRC32 0xf3252c32    Previous-GTIDs
# [empty]
# at 154
#180112 15:57:18 server id 1323308  end_log_pos 214 CRC32 0x6054f256    Rotate to mysql-bin.9223372036854775808  pos: 4
SET @@SESSION.GTID_NEXT= \'AUTOMATIC\' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[root@ZST1 logs]#
View Code

解析binlog可以在末尾看到Rotate to mysql-bin.9223372036854775808  pos: 4
也就是说再怎么切，也只能切到9223372036854775808，这个文件感觉有点不太正常，不受max_binlog_size限制，解析出的日志莫名不完整~
恢复原始：手工删除 mysql-bin.2147483647 这类大文件，然后修改 mysql-bin.index；或者直接清空logs文件夹，再重新启动数据库服务

四、参考文档

MySQL binlog后面的编号最大是多大：http://wubx.net/mysql-binlog-max-sequence/
High-Level Binary Log Structure and Contents：https://dev.mysql.com/doc/internals/en/binary-log-structure-and-contents.html
Binary Log Versions：https://dev.mysql.com/doc/internals/en/binary-log-versions.html
Event Structure：https://dev.mysql.com/doc/internals/en/event-structure.html

以上是关于手动创建binary log files和手动编辑binary log index file会有什么影响的主要内容，如果未能解决你的问题，请参考以下文章

Spring Boot - 没有写入日志文件（不尊重logging.file）

如何手动编辑 KSDS VSAM 文件的密钥？

LOGBACK手动加载配置文件

Mysql主从错误：could not find first log file name in binary....

使用 pip，我应该从 pip freeze 创建 requirements.txt，还是手动编辑 requirements.txt 文件？

ubuntu下手动安装MongoDB