1-MySQL - 日志管理

目录

about

centos7.9 + mysql5.7.20

本篇主要探讨MySQL中的几种日志，其中：

日志文件 选项 文件名/表名 程序
错误日志 --log-error host_name.err N/A
常规日志 --general_log host_name.log
general_log		 N/A
慢查询日志 --slow_query_log
--long_query_time		 host_name-slow.log
slow_log		 mysqldumpslow
二进制日志 --log-bin
--expire-logs-days		 host_name-bin.00001 mysqlbinlog
审计日志 --audit_log
--audit_log_file		 audit.log N/A

上面的几种日志种，我们主要关注：

  • 错误日志(error log)
  • 慢查询日志(slow log)
  • 二进制日志(bin log)

分别来看吧！

before

此时我的MySQL环境和配置是这样的，/etc/my.cnf：

[mysqld]
user=mysql
basedir=/opt/software/mysql
datadir=/data/mysql_data
server_id=6
port=3306
socket=/tmp/mysql.sock
secure-file-priv=/tmp
[mysql]
socket=/tmp/mysql.sock
# prompt=3306 [\\d]>

后续的相关操作和演示，都基于这个环境进行操作。

error log

错误日志(Error Log)部分比较简单，这部分主要记住，错误日志的作用、错误日志的存储位置配置、查看错误日志时的关注点和相关的参数。

错误日志的作用

错误日志的作用就是记录启动、日常运行、关闭过程中，MySQL的相关状态信息、警告信息、错误信息。

错误日志配置

在MySQL5.7中，MySQL默认将错误日志输出到控制台，而不是文件中，我们可以登录到MySQL中，根据相关参数进行确认：

mysql> select @@log_error;
+-------------+
| @@log_error |
+-------------+
| stderr      |
+-------------+
1 row in set (0.00 sec)

mysql> show variables like "log_error";
+---------------+--------+
| Variable_name | Value  |
+---------------+--------+
| log_error     | stderr |
+---------------+--------+
1 row in set (0.00 sec)

stderr意味着将错误日志输出到控制台。

那么我们也可以通过在配置文件(/etc/my.cnf)中配置，将错误日志输出到指定的文件中，重点关注下列参数：

  • log_error：错误日志位置。
  • log_warnings：在MySQL 5.7.2以前，该参数控制错误日志输入到文件的级别，在MySQL 5.7.2和更高版本中， log_warnings仍然允许使用，但是它映射到了 log_error_verbosity参数，映射关系如下：
    • log_warnings=0，等同于log_error_verbosity=1，仅将错误信息输入到文件。
    • log_warnings=1，等同于log_error_verbosity=2，仅将错误和警告信息输入到文件。
    • log_warnings=2，默认值，等同于log_error_verbosity=3，仅将错误(errors)和警告(warnings)及需要注意的信息(notes)信息输入到文件，另外如果将log_warnings的值设置的大于2的话，也是等于2。
    • 注意，在MySQL8.0中log_warnings参数将被删除。
  • log_error_verbosity，MySQL5.7.20版本更高版本中，用来替代log_warnings参数，用来控制服务器将错误，警告和注释消息写入错误日志的详细程度，默认值为3：
    • log_error_verbosity=1，将 Error messages输入到文件。
    • log_error_verbosity=2，将 Error and warning messages输入到文件。
    • log_error_verbosity=3，将 Error, warning, and information messages输入到文件。

来配置一下，然后重启MySQL服务生效：

[root@cs ~]# vim /etc/my.cnf 

[mysqld]
log_error=/data/mysql_data/mysql.err
# log_error_verbosity=3

[root@cs ~]# systemctl restart mysqld
[root@cs ~]# ls /data/mysql_data/*.err
/data/mysql_data/mysql.err

mysql> select @@log_error;
+----------------------------+
| @@log_error                |
+----------------------------+
| /data/mysql_data/mysql.err |
+----------------------------+
1 row in set (0.00 sec)

那现在我们的错误日志文件就能正常的记录相关的日志信息了。

flush logs

flush logs命令用来动态的刷新错误日志文件。

比如失手删除了错误日志，那么可以在不停机的情况下，来刷新日志，即该命令会检查错误日志是否存在，不存在则创建，如果文件存在则不会重新创建：

[root@cs ~]# ls /data/mysql_data/*.err				# 原来是有的
/data/mysql_data/mysql.err	
[root@cs ~]# rm -rf /data/mysql_data/mysql.err 		# 现在没有了
[root@cs ~]# ls /data/mysql_data/*.err
ls: cannot access /data/mysql_data/*.err: No such file or directory
[root@cs ~]# mysqladmin -uroot -p flush-logs		# 通过这个命令刷新log日志
Enter password: 
[root@cs ~]# ls /data/mysql_data/*.err				# 现在就有了
/data/mysql_data/mysql.err

当然，这个命令也可在登录到MySQL中进行执行：

[root@cs ~]# rm -rf /data/mysql_data/mysql.err 
[root@cs ~]# ls /data/mysql_data/*.err
ls: cannot access /data/mysql_data/*.err: No such file or directory
[root@cs ~]# mysql -uroot -p

mysql> flush logs;						# 就这个命令
Query OK, 0 rows affected (0.00 sec)

[root@cs ~]# ls /data/mysql_data/*.err
/data/mysql_data/mysql.err

注意：当log_error参数是stderr时，flush logs不生效，而只有配置了具体的错误日志路径之后，flush logs才有效。详情参考官网

查看错误日志时的关注点

错误日志怎么查看？就像查看普通文本一样查看！

那肯定不用说了，我们重点关注[error]信息。

而当你遇到error提示的信息时，选择▶ctrl+c▶Google▶ctrl+v......

注意，MySQL的错误日志，需要我们手动管理，以防止日志文件过大导致一些不必要的意外。

bin log

二进制日志(Bin Log)，也称之为复制日志(Replication Log)，是MySQL中最重要的日志，它的主要作用是：

  • 备份恢复必须依赖二进制日志
  • 主从环境必须依赖二进制日志

另外，bin log记录的是SQL层(逻辑层)的日志，且只记录变更的SQL语句，而不记录查询语句。

start bin log

bin log默认是关闭的。

想要开启bin log，首先要创建一个存储路径：

[root@cs ~]# mkdir /data/mysql_data/binlog
[root@cs ~]# chown -R mysql.mysql /data/mysql_data/binlog/

注意，我这里为了方便，将bin log和数据文件放在了一起，大家要根据自己的实际情况决定是否分开放，因为bin log文件也比较大，另一种考虑就是鸡蛋不要放在一个篮子里，因为你也不知道会不会有人不小心把你数据文件目录整个都删掉........

vim /etc/my.cnf，完事重启MySQL即可：

[mysqld]
server_id=6		
log_bin=/data/mysql_data/binlog/mysql-bin
binlog_format=row
# transaction_isolation=REPEATABLE-READ  -- 建议将隔离级别设置为RR级别

bin log中的重要参数：

  • log_bin，是否开启二进制日志，默认为0关闭，但通常将参数的值直接设置为一个bin log的保存路径。
    • mysql-bin是二进制文件的命名前缀。
  • server_id，当前主机的唯一号码，1~65535之间的随机选择一个，主从中保持唯一即可。
    • PS：5.6版本中单机无需配置，但主从中必须设置，5.7中直接当成默认参数来设置到配置文件中就完了。
  • binlog_format，记录二进制日志时的格式，MySQL5.7中默认是row，所以这个参数在配置文件中可以不写。
  • log_bin_basename，binlog的存储位置，但它通常被log_bin代替，所以这个参数在配置文件中也可以不写。
  • sync_binlog：决定将二进制日志刷写磁盘的模式，默认值为0，意为当事务提交之后，MySQL不做fsync之类的磁盘同步指令刷新binlog_cache中的信息到磁盘，而让Filesystem自行决定什么时候来做同步，或者cache满了之后才同步到磁盘。

以上这几个参数都可以登录到MySQL中，使用select @@命令进行查看。

当配置完成，重启MySQL后，就可以看到自动生成的日志文件了：

[root@cs ~]# systemctl restart mysqld
[root@cs ~]# ll /data/mysql_data/binlog/
total 8
-rw-r-----. 1 mysql mysql 154 Apr 22 18:20 mysql-bin.000001
-rw-r-----. 1 mysql mysql  41 Apr 22 18:20 mysql-bin.index

其中序号结尾的是二进制的日志文件，而index结尾的文件则记录了这些二进制文件的路径，而我们重点关注的是那些序号文件。

bin log中的日志格式

前面提过binlog是逻辑层的日志，记录的是变更的SQL语句，对于不同的变更的SQL语句，它的记录方式也有所区别：

  • DDL（数据定义语言），以语句方式(statement)原封不动的记录当前DDL操作。
  • DCL（数据控制语言），以语句方式(statement)原封不动的记录当前DCL操作。
  • DML（数据操作语言），只记录已经提交的事务的DML操作。

另外，DML操作也有三种记录模式，且受binlog_format参数控制，这也意味着DDL和DCL相关语句不受binlog_format参数控制。

基于SQL语句的复制(SBR,statement-based replication)模式

基于SQL语句的复制(SBR,statement-based replication)模式，MySQL5.6版本的默认方式，以语句方式(statement)原封不动的记录当前DML操作。

特点：日志可读性高，日志量小，但不够严谨。

更多细节

优点：

  • 历史悠久，技术成熟
  • binlog文件较小
  • binlog中包含了所有数据库更改信息，可以据此来审核数据库的安全等情况
  • binlog可以用于实时的还原，而不仅仅用于复制
  • 主从版本可以不一样，从服务器版本可以比主服务器版本高

缺点：

不是所有的UPDATE语句都能被复制，尤其是包含不确定操作的时候。
调用具有不确定因素的 UDF 时复制也可能出问题。
使用以下函数的语句也无法被复制：

  • LOAD_FILE()

  • UUID()

  • USER()

  • FOUND_ROWS()

  • SYSDATE() (除非启动时启用了 --sysdate-is-now 选项)

  • INSERT ... SELECT 会产生比 RBR 更多的行级锁

复制需要进行全表扫描(WHERE 语句中没有使用到索引)的 UPDATE 时，需要比 RBR 请求更多的行级锁
对于有 AUTO_INCREMENT 字段的 InnoDB表而言，INSERT 语句会阻塞其他 INSERT 语句。对于一些复杂的语句，在从服务器上的耗资源情况会更严重，而 RBR 模式下，只会对那个发生变化的记录产生影响，存储函数(不是存储过程)在被调用的同时也会执行一次 NOW() 函数，这个可以说是坏事也可能是好事，确定了的 UDF 也需要在从服务器上执行，数据表必须几乎和主服务器保持一致才行，否则可能会导致复制出错，执行复杂语句如果出错的话，会消耗更多资源。

UDF是mysql的一个拓展接口，UDF（Userdefined function）可翻译为用户自定义函数，这个是用来拓展Mysql的技术手段。

举个例子，如有个订单表，在上午十点产生了一个新的订单：

insert into order values(1, 'mi1', now());

这条插入记录以statement方式原封不动的记录到了bin log，那么如果11点数据库崩了，使用bin log做数据库恢复时，这个订单的创建时间，就是你恢复时的时间，而不是上午十点。这就是为什么说statement方式不严谨的原因。

基于行的复制(RBR,row-based replication)模式

基于行的复制(RBR,row-based replication)模式，MySQL5.7版本的默认方式，记录数据行的变化，但日志内容我们看不懂，需要借助工具来分析。

特点：日志的可读性低，日志量大，足够严谨。严谨到啥程度呢？如下面这条语句：

-- 如果 t1 表有 500W 行记录
update t1 set name="张开" where id>100;

上面的update语句基于row模式，那么row模式又是如何记录binlog呢？它会逐行记录变更操作，所以非常严谨，但也导致了日志量大。而如果是statement模式则只记录一个语句，虽然日志量小，但不够严谨。

更多细节

优点：

任何情况都可以被复制，这对复制来说是最安全可靠的。
多数情况下，从服务器上的表如果有主键的话，复制就会快了很多。
复制以下几种语句时的行锁更少：

  • INSERT ... SELECT
  • 包含 AUTO_INCREMENT 字段的 INSERT
  • 没有附带条件或者并没有修改很多记录的 UPDATE 或 DELETE 语句

执行 INSERT，UPDATE，DELETE 语句时锁更少。
从服务器上采用多线程来执行复制成为可能。

缺点：

binlog 大了很多。
复杂的回滚时 binlog 中会包含大量的数据。
主服务器上执行 UPDATE 语句时，所有发生变化的记录都会写到 binlog 中，而 SBR 只会写一次，这会导致频繁发生 binlog 的并发写问题。
UDF 产生的大 BLOB 值会导致复制变慢。
无法从 binlog 中看到都复制了写什么语句。
当在非事务表上执行一段堆积的SQL语句时，最好采用 SBR 模式，否则很容易导致主从服务器的数据不一致情况发生。

另外，针对系统库MySQL里面的表发生变化时的处理规则如下：

  • 如果是采用 INSERT，UPDATE，DELETE 直接操作表的情况，则日志格式根据 binlog_format 的设定而记录
  • 如果是采用 GRANT，REVOKE，SET PASSWORD 等管理语句来做的话，那么无论如何都采用 SBR 模式记录

注：采用 RBR 模式后，能解决很多原先出现的主键重复问题。

混合复制(MBR,mixed-based replication)模式

混合复制(MBR,mixed-based replication)模式，它会根据具体的SQL语句自动选择使用row模式还是statement模式来记录日志。

event

什么是事件(event)？

事件是binlog的最小记录单元。

对于DDL、DCL，一个语句就是一个事件。

对于DML语句来说，一个（已提交的）事务就是一个事件，如下面的例子，就被分为了4个事件：

begin;		120 - 340
DML1		340 - 460
DML2		460 - 570
commit;		570 - 680

再次强调，对于DML语句来说，只记录已经提交的事务。

另外，这里还要注意，只有在当前的bin log中，一个事务才被分为4个小事务，然后被记录到了bin log中，但逻辑上和其它地方，如GTID中，从begin到commit，它还是一个完整的事务。

事件的作用

用于binlog的截取、分析、恢复。

事件的构成

一个事件有三部分组成：

  • 事件的开始位置，在binlog中用at标识。注意，一个事件的开始其实也是上一个事件的结束位置。
  • 事件的内容。
  • 事件的结束，在binlog中用end_log_pos标识，注意，一个事件的结束其实也是下一个事件的开始位置。

而事件开始/结束的数字则是事件(的相对位置)号(position)，它标识事件在整个bin log中的相对位置，我们可以根据这个position号来截取相应的事件，进行数据恢复。

查看事件

当我们开启了binlog，它就会默默的记录变更的SQL操作，并且按照一定的规则会自动的拆分日志：

mysql> show binary logs;			-- 返回log_basename下所有的binlog文件
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       154 |
+------------------+-----------+
1 row in set (0.00 sec)

mysql> flush logs;					-- 手动刷新log，MySQL会自动创建一个新的bin log文件
Query OK, 0 rows affected (0.01 sec)

mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       201 |
| mysql-bin.000002 |       154 |
+------------------+-----------+
2 rows in set (0.00 sec)

mysql> show master status;			-- 查询MySQL正在使用的bin log文件
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000002 |      154 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

mysql> system ls /data/mysql_data/binlog
mysql-bin.000001  mysql-bin.000002  mysql-bin.index

-- mysql-bin.index记录bin log 文件的路径，MySQL内部使用，我们很少关注
mysql> system cat /data/mysql_data/binlog/mysql-bin.index   
/data/mysql_data/binlog/mysql-bin.000001
/data/mysql_data/binlog/mysql-bin.000002

上例中，Log_name会递增，也就是会自动拆分为多个文件，而File_size则指的是当前binlog中最大的事件结束位置。

另外，单位时间内，MySQL只会使用最后一个binlog文件，历史文件不再变动了。

那在什么情况下MySQL会自动的拆分binlog呢？

  • 手动flush logs;时，该命令可以重复运行。
  • MySQL服务重启后。

我们来看看bin log文件内容：

-- bin log文件是特殊文件，所以不能用普通的cat 或者 vim命令去查看文件内容
mysql> system file /data/mysql_data/binlog/mysql-bin.000001
/data/mysql_data/binlog/mysql-bin.000001: MySQL replication log

-- MySQL提供了相关命令来供我们查看bin log文件
-- 当然，首先我们要确认MySQL正在使用的bin log文件
mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000002 |      154 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

-- 然后使用show binlog events in 'bin log文件名'来查看文件内容
-- 由于flush logs 后，我们基本没有做什么操作，bin log并没有记录什么东西，下面 4~154 是MySQL bin log文件的头信息
mysql> show binlog events in 'mysql-bin.000002';
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                  |
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
| mysql-bin.000002 |   4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4 |
| mysql-bin.000002 | 123 | Previous_gtids |         6 |         154 |                                       |
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
2 rows in set (0.00 sec)

-- 原来的mysql-bin.000001中记录了 flush logs 的操作
mysql> show binlog events in 'mysql-bin.000001';
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                  |
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
| mysql-bin.000001 |   4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4 |
| mysql-bin.000001 | 123 | Previous_gtids |         6 |         154 |                                       |
| mysql-bin.000001 | 154 | Rotate         |         6 |         201 | mysql-bin.000002;pos=4                |
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
3 rows in set (0.00 sec)

bin log文件的position从4开始到154，都是算是头信息，所以，我们也不要用vim之类的命令去操作它，以免造成文件的损坏。

接下来我们做些操作，产生一些binlog日志，再来观察它是如何记录的。

create database binlog_test;
use binlog_test			
create table t1(id int);	
insert into t1 value(11);

有了操作，再来看binlog中，如何记录的：

mysql> show binlog events in 'mysql-bin.000002';
+------------------+-----+----------------+-----------+-------------+--------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                       |
+------------------+-----+----------------+-----------+-------------+--------------------------------------------+
| mysql-bin.000002 |   4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4      |
| mysql-bin.000002 | 123 | Previous_gtids |         6 |         154 |                                            |
| mysql-bin.000002 | 154 | Anonymous_Gtid |         6 |         219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'       |
| mysql-bin.000002 | 219 | Query          |         6 |         334 | create database binlog_test                |
| mysql-bin.000002 | 334 | Anonymous_Gtid |         6 |         399 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'       |
| mysql-bin.000002 | 399 | Query          |         6 |         510 | use `binlog_test`; create table t1(id int) |
| mysql-bin.000002 | 510 | Anonymous_Gtid |         6 |         575 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'       |
| mysql-bin.000002 | 575 | Query          |         6 |         654 | BEGIN                                      |
| mysql-bin.000002 | 654 | Table_map      |         6 |         706 | table_id: 264 (binlog_test.t1)             |
| mysql-bin.000002 | 706 | Write_rows     |         6 |         746 | table_id: 264 flags: STMT_END_F            |
| mysql-bin.000002 | 746 | Xid            |         6 |         777 | COMMIT /* xid=24 */                        |
+------------------+-----+----------------+-----------+-------------+--------------------------------------------+
11 rows in set (0.00 sec)

上面的语句是查询MySQL当前正在使用的binlog文件的所有事件信息。每一行就是一个事件。

对照上图，binlog记录的格式大致就是这样的了，这里暂时"忽略"GTID。每一个事件的结束位置也就是下一个事件的开始位置。针对于DCL语句，直接原封不动的记录SQL语句，而针对于DML语句来说，则记录的是一个完整的事务过程。

当然了，如果bin log很大，我们还可以通过limit和from过滤结果：

-- limit 就跟普通的 limit 一样
mysql> show binlog events in "mysql-bin.000002" limit 3;  -- 截取前三个事件
mysql> show binlog events in "mysql-bin.000002" limit 3,3;	-- 从第四个事件开始往后截取3个事件

-- -- from 从指定事件号开始往后截取
mysql> show binlog events in "mysql-bin.000002" from 334;	
mysql> show binlog events in "mysql-bin.000002" from 334 limit 3;	-- 从334事件号开始，往后截取3个事件

也可以通过-e和文本处理工具过滤结果：

[root@cs ~]# mysql -uroot -p123 -e 'show binlog events in "mysql-bin.000002";'
[root@cs ~]# mysql -uroot -p123 -e 'show binlog events in "mysql-bin.000002";' | grep create
mysql: [Warning] Using a password on the command line interface can be insecure.
mysql-bin.000002	219	Query	6	334	create database binlog_test
mysql-bin.000002	399	Query	6	510	use `binlog_test`; create table t1(id int)

日志截取

截取日志的核心就是从binlog文件中定位事件的起点和终点

我们知道了binlog的事件怎么过滤、查看，我们再来看看binlog文件的内容长啥样？

-- 查看binlog内容，mysqlbinlog命令后跟binlog文件路径
mysqlbinlog mysql-bin.000002

-- 如下示例，返回的内容一般人看不懂
[root@cs ~]# mysqlbinlog /data/mysql_data/binlog/mysql-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210423 11:23:46 server id 6  end_log_pos 123 CRC32 0x769effea 	Start: binlog v 4, server v 5.7.20-log created 210423 11:23:46
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
wj2CYA8GAAAAdwAAAHsAAAABAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
Aer/nnY=
'/*!*/;
# at 123
#210423 11:23:46 server id 6  end_log_pos 154 CRC32 0xac48ed13 	Previous-GTIDs
# [empty]
# at 154
#210423 11:42:41 server id 6  end_log_pos 219 CRC32 0x7780d393 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#210423 11:42:41 server id 6  end_log_pos 334 CRC32 0x47362ebf 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1619149361/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create database binlog_test
/*!*/;
# at 334
#210423 11:43:33 server id 6  end_log_pos 399 CRC32 0xfd23e6a5 	Anonymous_GTID	last_committed=1	sequence_number=2	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 399
#210423 11:43:33 server id 6  end_log_pos 510 CRC32 0xead4783c 	Query	thread_id=3	exec_time=0	error_code=0
use `binlog_test`/*!*/;
SET TIMESTAMP=1619149413/*!*/;
create table t1(id int)
/*!*/;
# at 510
#210423 11:43:43 server id 6  end_log_pos 575 CRC32 0xcee071d8 	Anonymous_GTID	last_committed=2	sequence_number=3	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 575
#210423 11:43:43 server id 6  end_log_pos 654 CRC32 0x4e6d8c89 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1619149423/*!*/;
BEGIN
/*!*/;
# at 654
#210423 11:43:43 server id 6  end_log_pos 706 CRC32 0x2e042787 	Table_map: `binlog_test`.`t1` mapped to number 264
# at 706
#210423 11:43:43 server id 6  end_log_pos 746 CRC32 0x2fc012b0 	Write_rows: table id 264 flags: STMT_END_F

BINLOG '
b0KCYBMGAAAANAAAAMICAAAAAAgBAAAAAAEAC2JpbmxvZ190ZXN0AAJ0MQABAwABhycELg==
b0KCYB4GAAAAKAAAAOoCAAAAAAgBAAAAAAEAAgAB//4LAAAAsBLALw==
'/*!*/;
# at 746
#210423 11:43:43 server id 6  end_log_pos 777 CRC32 0x372c9dc1 	Xid = 24
COMMIT/*!*/;
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*/;


-- 将binlog导出为sql文件，用于数据恢复
[root@cs ~]# mysqlbinlog /data/mysql_data/binlog/mysql-bin.000002 > /tmp/binlog1.sql
[root@cs ~]# ls /tmp/*sql
/tmp/binlog1.sql

上面的输出结果，你也一定看不懂，没事，一般人都看不懂！

-- 下面的命令稍微的翻译了下看不懂的字符，连蒙带猜大体能知道记录的是啥了
mysqlbinlog --base64-output=decode-rows -vv mysql-bin.000002

-- 过滤指定数据库下的binlog
mysqlbinlog -d binlog_test --base64-output=decode-rows -vv mysql-bin.000002

-- 根据时间过滤
mysqlbinlog --start-datetime="2020-11-25 11:21:36" --base64-output=decode-rows -vv mysql-bin.000002
mysqlbinlog --start-datetime="2020-11-25 11:21:36" --stop-datetime="2020-11-25 11:30:20" --base64-output=decode-rows -vv mysql-bin.000002

-- 根据事务号过滤
mysqlbinlog --start-position=575 mysql-bin.000002
mysqlbinlog --start-position=575 --stop-position=777 mysql-bin.000002

扯了半天，也看了半天， 目的就是查询和过滤binlog，便于后续按需截取日志，做数据恢复。

使用bin log进行数据恢复示例

伪造事故现场

-- 首先确认当前正在使用的bin log文件
mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000002 |      777 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

-- 执行下面的SQL，伪造一些数据和误删除操作
create database binlog_test2;
use binlog_test2
create table t1(n int);
insert into t1 values(11),(22),(33);
update t1 set n=111 where n=11;
drop table t1;
drop database binlog_test2;

恢复

首先确定日志的恢复范围，肯定是恢复到删除表、删除库之前的事件范围：

mysql> show binlog events in 'mysql-bin.000002';
+------------------+------+----------------+-----------+-------------+---------------------------------------------------------------+
| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                                          |
+------------------+------+----------------+-----------+-------------+---------------------------------------------------------------+
| mysql-bin.000002 |    4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4                         |
| mysql-bin.000002 |  123 | Previous_gtids |         6 |         154 |                                                               |
| mysql-bin.000002 |  154 | Anonymous_Gtid |         6 |         219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 |  219 | Query          |         6 |         334 | create database binlog_test                                   |
| mysql-bin.000002 |  334 | Anonymous_Gtid |         6 |         399 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 |  399 | Query          |         6 |         510 | use `binlog_test`; create table t1(id int)                    |
| mysql-bin.000002 |  510 | Anonymous_Gtid |         6 |         575 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 |  575 | Query          |         6 |         654 | BEGIN                                                         |
| mysql-bin.000002 |  654 | Table_map      |         6 |         706 | table_id: 264 (binlog_test.t1)                                |
| mysql-bin.000002 |  706 | Write_rows     |         6 |         746 | table_id: 264 flags: STMT_END_F                               |
| mysql-bin.000002 |  746 | Xid            |         6 |         777 | COMMIT /* xid=24 */                                           |
| mysql-bin.000002 |  777 | Anonymous_Gtid |         6 |         842 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 |  842 | Query          |         6 |         960 | create database binlog_test2                                  |
| mysql-bin.000002 |  960 | Anonymous_Gtid |         6 |        1025 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 | 1025 | Query          |         6 |        1137 | use `binlog_test2`; create table t1(n int)                    |
| mysql-bin.000002 | 1137 | Anonymous_Gtid |         6 |        1202 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 | 1202 | Query          |         6 |        1282 | BEGIN                                                         |
| mysql-bin.000002 | 1282 | Table_map      |         6 |        1335 | table_id: 265 (binlog_test2.t1)                               |
| mysql-bin.000002 | 1335 | Write_rows     |         6 |        1385 | table_id: 265 flags: STMT_END_F                               |
| mysql-bin.000002 | 1385 | Xid            |         6 |        1416 | COMMIT /* xid=33 */                                           |
| mysql-bin.000002 | 1416 | Anonymous_Gtid |         6 |        1481 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 | 1481 | Query          |         6 |        1561 | BEGIN                                                         |
| mysql-bin.000002 | 1561 | Table_map      |         6 |        1614 | table_id: 265 (binlog_test2.t1)                               |
| mysql-bin.000002 | 1614 | Update_rows    |         6 |        1660 | table_id: 265 flags: STMT_END_F                               |
| mysql-bin.000002 | 1660 | Xid            |         6 |        1691 | COMMIT /* xid=34 */                                           |
| mysql-bin.000002 | 1691 | Anonymous_Gtid |         6 |        1756 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 | 1756 | Query          |         6 |        1887 | use `binlog_test2`; DROP TABLE `t1` /* generated by server */ |
| mysql-bin.000002 | 1887 | Anonymous_Gtid |         6 |        1952 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 | 1952 | Query          |         6 |        2053 | drop database binlog_test2                                    |
+------------------+------+----------------+-----------+-------------+---------------------------------------------------------------+
29 rows in set (0.00 sec)

根据分析bin log的事件，确认事件号的范围842~1691，然后我们开始执行恢复过程。

  • 首先截取bin log并导出：
-- 根据刚才确认的事件号的范围，将该范围内的bin log导出来，用于后续的数据恢复
[root@cs ~]# mysqlbinlog --start-position=842 --stop-position=1691 /data/mysql_data/binlog/mysql-bin.000002 > /tmp/binlog2.sql
[root@cs ~]# ls /tmp/binlog*
/tmp/binlog1.sql  /tmp/binlog2.sql
  • 根据bin log进行数据恢复：
-- 进行数据恢复也会被记录到bin log中，但这部分操作无需记录到bin log中，所以临时关闭bin log的记录
mysql> set sql_log_bin=0;
Query OK, 0 rows affected (0.00 sec)

-- 根据之前导出的sql文件进行恢复
mysql> source /tmp/binlog2.sql  
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)
......

-- 数据恢复成功
mysql> select * from binlog_test2.t1;
+------+
| n    |
+------+
|  111 |
|   22 |
|   33 |
+------+
3 rows in set (0.00 sec)

-- 再打开刚才临时关闭的bin log
mysql> set sql_log_bin=1;
Query OK, 0 rows affected (0.00 sec)

ok，恢复完毕。

以上示例相对简单，只是让你体会下如何使用bin log进行数据恢复的。但实际应用中，往往面对的是比较复杂且无比麻烦的场景。

随便举个例子，你用position号如何进行分段截取？

我们可以用GTID来帮忙！

GTID

在上一小节中，当你查看bin log事件时，"忽略"的那些带有"GTID"的行，到底是什么呢？

mysql> show binlog events in 'mysql-bin.000002';
+------------------+------+----------------+-----------+-------------+---------------------------------------------------------------+
| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                                          |
+------------------+------+----------------+-----------+-------------+---------------------------------------------------------------+
| mysql-bin.000002 |    4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4                         |
| mysql-bin.000002 |  123 | Previous_gtids |         6 |         154 |                                                               |
| mysql-bin.000002 |  154 | Anonymous_Gtid |         6 |         219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |
| mysql-bin.000002 |  219 | Query          |         6 |         334 | create database binlog_test                                   |
| mysql-bin.000002 |  334 | Anonymous_Gtid |         6 |         399 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                          |

GTID，全称是Global Transation ID(全局事务ID)，它的特点是全局且唯一，也就是它为每个事务生成一个全局的唯一ID，多用于备份恢复中，这里我们先来简单了解。GTID的另一个特点是具有幂等性，简单来说，在开启GTID后，MySQL在根据bin log做数据恢复时，重复的GTID事务不会再执行了，多用于备份恢复中。

GTID是MySQL5.6版本的新特性，并且在MySQL5.7中该特性得到增强。另外，在MySQL5.6和5.7中，默认是关闭的，但需要注意的是，在5.7中，虽然默认是关闭的，但它仍然会给每个事务创建一个GTID，只不过是匿名的，这也就是为什么它会出现在bin log事件中的原因，但如果GTID没有开启时，通常我们会忽略这个匿名的GTID。

为了更好的了解GTID，我们先开启该功能。

开启GTID

vim /etc/my.cnf：

[root@cs ~]# vim /etc/my.cnf

[mysqld]
gtid-mode=on		
enforce-gtid-consistency=true	-- 强制gtid的一致性

[root@cs ~]# systemctl restart mysqld

别忘了重启数据库。

想要看到GTID的效果，我们还需要做点什么，比如创建个数据库：

-- 由于MySQL服务重启，又生成了一个新的 bin log 文件
mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000003 |      154 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0.01 sec)

mysql> create database gt_test1;
Query OK, 1 row affected (0.00 sec)

-- 在Executed_Gtid_Set栏，多了个GTID
mysql> show master status;
+------------------+----------+--------------+------------------+----------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                      |
+------------------+----------+--------------+------------------+----------------------------------------+
| mysql-bin.000003 |      325 |              |                  | ce11c46f-56f8-11eb-9d69-000c29df6adb:1 |
+------------------+----------+--------------+------------------+----------------------------------------+
1 row in set (0.00 sec)

上面的GTID的我们用:分为两部分：

  • 左半部分，是唯一的UUID，这个UUID是哪来的？如下示例所示，这个UUID来自于MySQL初始化时或者MySQL重启时，得到的一个UUID，然后存储到了MySQL数据目录中的auto.cnf中，该UUID是当前MySQL实例的唯一的UUID，因为具有唯一性，所以GTID也用了它。
mysql> system ls /data/mysql_data/auto.cnf
/data/mysql_data/auto.cnf
mysql> system cat /data/mysql_data/auto.cnf
[auto]
server-uuid=ce11c46f-56f8-11eb-9d69-000c29df6adb
  • 至于右半部分，则表示说，自从开启GTID后，bin log中总共记录了多少个事务。而我们在开启GTID后，创建了数据操作，它算一个事务，所以，右半部分是1。注意，它记录的是完整的事务。
mysql> use gt_test1
Database changed
mysql> create table t1(id int);    -- 创建表，这又是一个事务
Query OK, 0 rows affected (0.01 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+------------------+----------+--------------+------------------+------------------------------------------+
| mysql-bin.000003 |      495 |              |                  | ce11c46f-56f8-11eb-9d69-000c29df6adb:1-2 |
+------------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

mysql> insert into t1 values(1);    -- 插入数据，这是个完整的事务
Query OK, 1 row affected (0.00 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+------------------+----------+--------------+------------------+------------------------------------------+
| mysql-bin.000003 |      756 |              |                  | ce11c46f-56f8-11eb-9d69-000c29df6adb:1-3 |
+------------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

我们再来看下bin log的变化：

mysql> show binlog events in 'mysql-bin.000003';
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                              |
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
| mysql-bin.000003 |   4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4                             |
| mysql-bin.000003 | 123 | Previous_gtids |         6 |         154 |                                                                   |
| mysql-bin.000003 | 154 | Gtid           |         6 |         219 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:1' |
| mysql-bin.000003 | 219 | Query          |         6 |         325 | create database gt_test1                                          |
| mysql-bin.000003 | 325 | Gtid           |         6 |         390 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:2' |
| mysql-bin.000003 | 390 | Query          |         6 |         495 | use `gt_test1`; create table t1(id int)                           |
| mysql-bin.000003 | 495 | Gtid           |         6 |         560 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:3' |
| mysql-bin.000003 | 560 | Query          |         6 |         636 | BEGIN                                                             |
| mysql-bin.000003 | 636 | Table_map      |         6 |         685 | table_id: 266 (gt_test1.t1)                                       |
| mysql-bin.000003 | 685 | Write_rows     |         6 |         725 | table_id: 266 flags: STMT_END_F                                   |
| mysql-bin.000003 | 725 | Xid            |         6 |         756 | COMMIT /* xid=15 */                                               |
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
11 rows in set (0.00 sec)

变化很明显:

-- before
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'     

-- after
SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:1'

那，说了这么多，GTID的好处也即将体现出来，我们在截取和恢复数据时，就可以根据GTID值来做，而不是像之前根据position号来做了。

来个示例体会下。

基于GTID的bin log数据恢复示例

伪造事故现场

-- 首先，确认当前使用的bin log 文件
mysql> show master status;
+------------------+----------+--------------+------------------+------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+------------------+----------+--------------+------------------+------------------------------------------+
| mysql-bin.000003 |      756 |              |                  | ce11c46f-56f8-11eb-9d69-000c29df6adb:1-3 |
+------------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

-- 然后，某个小谁失手把刚才创建的gt_test1数据库删了....
mysql> drop database gt_test1;
Query OK, 1 row affected (0.01 sec)

恢复

首先还是确定要恢复的数据GTID范围：

mysql> show binlog events in 'mysql-bin.000003';
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                              |
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
| mysql-bin.000003 |   4 | Format_desc    |         6 |         123 | Server ver: 5.7.20-log, Binlog ver: 4                             |
| mysql-bin.000003 | 123 | Previous_gtids |         6 |         154 |                                                                   |
| mysql-bin.000003 | 154 | Gtid           |         6 |         219 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:1' |
| mysql-bin.000003 | 219 | Query          |         6 |         325 | create database gt_test1                                          |
| mysql-bin.000003 | 325 | Gtid           |         6 |         390 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:2' |
| mysql-bin.000003 | 390 | Query          |         6 |         495 | use `gt_test1`; create table t1(id int)                           |
| mysql-bin.000003 | 495 | Gtid           |         6 |         560 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:3' |
| mysql-bin.000003 | 560 | Query          |         6 |         636 | BEGIN                                                             |
| mysql-bin.000003 | 636 | Table_map      |         6 |         685 | table_id: 266 (gt_test1.t1)                                       |
| mysql-bin.000003 | 685 | Write_rows     |         6 |         725 | table_id: 266 flags: STMT_END_F                                   |
| mysql-bin.000003 | 725 | Xid            |         6 |         756 | COMMIT /* xid=15 */                                               |
| mysql-bin.000003 | 756 | Gtid           |         6 |         821 | SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:4' |
| mysql-bin.000003 | 821 | Query          |         6 |         925 | drop database gt_test1                                            |
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
13 rows in set (0.00 sec)

可以很清晰的看到，GTID编号1~3的范围是我们要截取的日志范围，终于不用小心翼翼的去捋position号了！

来看命令：

-- 确认下范围对不对
[root@cs ~]# mysqlbinlog --include-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:1-3' --base64-output=decode-rows -vv /data/mysql_data/binlog/mysql-bin.000003 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210423 14:39:10 server id 6  end_log_pos 123 CRC32 0xa91b5c44 	Start: binlog v 4, server v 5.7.20-log created 210423 14:39:10 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 123
#210423 14:39:10 server id 6  end_log_pos 154 CRC32 0xfc7e1a23 	Previous-GTIDs
# [empty]
# at 154
#210423 14:43:06 server id 6  end_log_pos 219 CRC32 0xdb400634 	GTID	last_committed=0	sequence_number=1	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:1'/*!*/;
# at 219
#210423 14:43:06 server id 6  end_log_pos 325 CRC32 0x7911f05c 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1619160186/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create database gt_test1
/*!*/;
# at 325
#210423 14:58:55 server id 6  end_log_pos 390 CRC32 0x742ac9ab 	GTID	last_committed=1	sequence_number=2	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:2'/*!*/;
# at 390
#210423 14:58:55 server id 6  end_log_pos 495 CRC32 0x12523283 	Query	thread_id=3	exec_time=0	error_code=0
use `gt_test1`/*!*/;
SET TIMESTAMP=1619161135/*!*/;
create table t1(id int)
/*!*/;
# at 495
#210423 14:59:08 server id 6  end_log_pos 560 CRC32 0xfb9346a1 	GTID	last_committed=2	sequence_number=3	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ce11c46f-56f8-11eb-9d69-000c29df6adb:3'/*!*/;
# at 560
#210423 14:59:08 server id 6  end_log_pos 636 CRC32 0xe3462a78 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1619161148/*!*/;
BEGIN
/*!*/;
# at 636
#210423 14:59:08 server id 6  end_log_pos 685 CRC32 0xdfd026bf 	Table_map: `gt_test1`.`t1` mapped to number 266
# at 685
#210423 14:59:08 server id 6  end_log_pos 725 CRC32 0xc3d34a13 	Write_rows: table id 266 flags: STMT_END_F
### INSERT INTO `gt_test1`.`t1`
### SET
###   @1=1 /* INT meta=0 nullable=1 is_null=0 */
# at 725
#210423 14:59:08 server id 6  end_log_pos 756 CRC32 0x3dacddaf 	Xid = 15
COMMIT/*!*/;
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@cs ~]# mysqlbinlog --include-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:1-3' /data/mysql_data/binlog/mysql-bin.000003 > /tmp/gt_test1.sql

完事之后，开始恢复，这个套路就跟之前恢复一样了：

-- 还是先临时关闭bin log,让接下来的恢复数据操作不会产生新的日志
mysql> set sql_log_bin=0;
Query OK, 0 rows affected (0.00 sec)


-- 然后读文件恢复
mysql> source /tmp/gt_test1.sql
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

ERROR 1049 (42000): Unknown database 'gt_test1'
Query OK, 0 rows affected (0.00 sec)

ERROR 1046 (3D000): No database selected
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

然后，你在上面的一堆输出中，找出了ERROR信息，报错没找到gt_test1数据库。先不说产生的原因，其结果就是数据恢复失败！！

那失败的原因是什么呢？还记得上面说的GTID的幂等性特性么？就是该特性捣的鬼！因为在根据GTID恢复数据时，MySQL发现这些GTID已经存在了，那么MySQL就不会重新执行了......这好处不言而喻，在备份恢复时，放弃那些重复的事务，提高备份恢复效率，但在这里已经影响我们的恢复操作了。

怎么解决呢？思路就是将截取的数据导出到文件时，忽略掉GTID，那么在恢复时，MySQL就会认为是新操作，达到数据恢复的目的：

[root@cs ~]# mysqlbinlog --skip-gtids --include-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:1-3' /data/mysql_data/binlog/mysql-bin.000003 > /tmp/gt_test2.sql

mysql> source /tmp/gt_test2.sql
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)
......

-- 数据恢复完成
mysql> select * from gt_test1.t1;
+------+
| id   |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

-- 别忘了这个操作
mysql> set sql_log_bin=1;
Query OK, 0 rows affected (0.00 sec)

-- 你也可以自己对比下加了 --skip-gtids 参数后，导出的两个文件有啥不同之处

再来看其他的命令，也即是分段截取导出。

-- 导出GTID范围是1-10的，但排除其中3号GTID
mysqlbinlog --skip-gtids --include-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:1-10' --exclude-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:3' /data/mysql_data/binlog/mysql-bin.000003 > /tmp/gt_test3.sql 

-- 跳过其中多个GTID
mysqlbinlog --skip-gtids --include-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:1-10' --exclude-gtids='ce11c46f-56f8-11eb-9d69-000c29df6adb:3,ce11c46f-56f8-11eb-9d69-000c29df6adb:5' /data/mysql_data/binlog/mysql-bin.000003 > /tmp/gt_test4.sql

当然了，这里的GTID必须都存在才行。

关于GTID我们就先了解到这里，其他应用我们讲到相关部分再聊。

日志过期策略

默认的，如果人工不进行干预，MySQL的bin log会一直记录下去......

所以，我们还需要了解如何清理bin log，也就是了解bin log日志的过期策略。

首先，不能使用系统的rm或者别的手段来清理日志，而是要采用MySQL的命令来清理日志。

当然，通常bin log的过期策略要根据备份策略来决定，这里我们先了解相关命令即可。

自动清理

mysql> select @@expire_logs_days;
+--------------------+
| @@expire_logs_days |
+--------------------+
|                  0 |
+--------------------+
1 row in set (0.01 sec)

默认是0表示是永不过期，当然你也可以设置过期时间：

mysql> set global expire_logs_days=15;

-- vim /etc/my.cnf
[mysqld]
expire_logs_days=15

实际工作中，建议至少保留两个全备周期+1的bin log。

手工清理

-- 根据当前时间，删除指定天数以前的日志
PURGE BINARY LOGS BEFORE now() - INTERVAL 3 day;

-- 将指定bin log文件序号前的都删除，如将000010号文件之前的文件都删除
PURGE BINARY LOGS TO 'mysql-bin.000010';

再多说一句，如何让bin log文件序号重置从0开始呢？

-- 慎用(禁止)的命令，尤其是主从环境下禁止在主库使用，但单实例情况下可以用
mysql> reset master;
Query OK, 0 rows affected (0.00 sec)

mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       154 |
+------------------+-----------+
1 row in set (0.00 sec)

bin log日志是如何滚动的？

这里总结下bin log日志的滚动方式：

  • 重启MySQL时。

  • 当文件大小达到max_binlog_size值的上限时。

mysql> select @@max_binlog_size as "字节", @@max_binlog_size / 1024 / 1024 as "MB";
+------------+---------------+
| 字节       | MB            |
+------------+---------------+
| 1073741824 | 1024.00000000 |
+------------+---------------+
1 row in set (0.07 sec)

  • 通过flush logs;滚动日志。可以设置定时刷新。

  • 备份时，也可以通过参数设置自动滚动。

slow log

慢日志(Slow Log)，也称慢查询日志。主要记录低效的SQL语句，便于我们后续对这些低效的SQL进行针对性的优化，以提高MySQL的性能。

start slow log

慢日志功能默认是关闭的：

-- 默认该功能是关闭的
mysql> select @@slow_query_log;
+------------------+
| @@slow_query_log |
+------------------+
|                0 |
+------------------+
1 row in set (0.00 sec)

我这里自定义了一个慢日志的存储路径：

[root@cs ~]# mkdir -p /logs/mysql_logs/slowlogs
[root@cs ~]# chown -R mysql.mysql /logs/mysql_logs/slowlogs/

开启慢日志，vim /etc/my.cnf，然后重启MySQL:

[mysqld]
slow_query_log=1
slow_query_log_file=/logs/mysql_logs/slowlogs/slow.log
long_query_time=0.2
log_queries_not_using_indexes=1

以上：

  • slow_query_log：默认为0表示关闭，设置为1表示开启慢日志记录功能。
  • slow_query_log_file：慢日志记录的存储位置。当然，它默认存储在你MySQL的数据目录内，名叫主机名-slow.log。但我们一般都是日志和数据分离，所以都选择自定义日志位置。
  • 符合以下条件的才记录到慢日志中：
    • long_query_time：查询语句查询时间超过long_query_time时，默认是10秒。这个参数需要根据实际的应用场景来设置。
    • log_queries_not_using_indexes：查询语句没走索引时，1表示开启该功能。当然，你也可以直接将这个参数填写到配置文件中，而不用赋值，也可以的。

注意，慢日志文件在MySQL服务重启后，就会被创建，但如果在MySQL运行期间，手动删除了慢日志文件，MySQL不会自动的创建，除非重启MySQL服务。

关于`long_query_time`

请求的响应时间(Response Time)：从客户端发出请求到得到响应的整个时间，包括网络响应时间+应用程序响应时间。

用户接受准则：2~5~10（或3~5~8或者2~5~8)原则

例如2~5~10原则，即按照正常用户体验，如果用户能够在2秒内得到响应，会感觉速度很快，如果2-5秒得到响应，用户感觉系统的响应速度还不多，在5-10秒之内得到响应时，用户会感觉系统的响应速度慢，但是可以接受，超过10秒后还没有响应，用户就会感觉不能够接受。

不同行业不同业务可接受的响应时间是不同的，一般情况，对于在线实时交易：

互联网企业：500毫秒以下，例如淘宝业务10毫秒左右。
金融企业：1秒以下为佳，部分复杂业务3秒以下。
保险企业：3秒以下为佳。
制造业：5秒以下为佳。
PS：数据来自于阿里云规范，但网站的RT受网络、硬件、软件架构、数据库的综合影响，而数据库只是其中一小部分，所以针对long_query_time的设置需要结合实际场景进行设置的。
而数据库性能测试的重点，就是在整个环节中，通过性能测试，将数据库的问题排除出去。

https://www.cnblogs.com/Neeo/articles/12482772.html#响应时间rt

现在我们可以准备些数据然后执行一些比较慢的SQL查询操作，让这些语句记录到日志中去。

准备数据 
-- MYSQL version 5.7.20
-- mysql -uroot -p123 <pressure.sql


DROP DATABASE IF EXISTS pp;
CREATE DATABASE pp CHARSET=utf8mb4 collate utf8mb4_bin;
USE pp;
SET AUTOCOMMIT=0;

DROP TABLE IF EXISTS pressure;

CREATE TABLE pressure(
id INT,
num INT,
k1 CHAR(2),
k2 CHAR(4),
dt TIMESTAMP
)ENGINE=INNODB CHARSET=utf8;

DELIMITER //
CREATE PROCEDURE rand_data(IN num INT)
BEGIN
DECLARE str CHAR(62) DEFAULT 'abcdefghijklmnopqrstuvwxyzABCDEFJHIJKLMNOPQRSTUVWXYZ0123456789';
DECLARE str2 CHAR(2);
DECLARE str4 CHAR(4);
DECLARE i INT DEFAULT 0;
WHILE i<num DO
SET str2=CONCAT(SUBSTRING(str,1+FLOOR(RAND()*61),1),SUBSTRING(str,1+FLOOR(RAND()*61),1));
SET str4=CONCAT(SUBSTRING(str,1+FLOOR(RAND()*61),2),SUBSTRING(str,1+FLOOR(RAND()*61),2));
SET i=i+1;
INSERT INTO pressure VALUES (i,FLOOR(RAND()*num),str2,str4,NOW());
END WHILE;
END //
DELIMITER ;

call rand_data(5000000);
commit;

随便写一些查询语句，让慢语句被记录：

select count(*) from pp.pressure;
select * from pp.pressure where id>450000 limit 10;
select num, count(id) from pp.pressure where id<100000 group by num limit 10;
select * from pp.pressure where id>800000 order by k1 limit 10;
select num from pp.pressure group by num limit 10;

你可以让以上语句重复执行个三四次，使模拟的慢日志更逼真。

现在，我们看看慢日志中有没有记录上：

[root@cs ~]# cat /logs/mysql_logs/slowlogs/slow.log | head -n 15
/opt/software/mysql/bin/mysqld, Version: 5.7.20-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 2021-04-25T02:04:15.019553Z
# User@Host: root[root] @ localhost []  Id:     3
# Query_time: 1.365438  Lock_time: 0.000073 Rows_sent: 1  Rows_examined: 5000000
use pp;
SET timestamp=1619316255;
select count(*) from pp.pressure;
# Time: 2021-04-25T02:04:15.166902Z
# User@Host: root[root] @ localhost []  Id:     3
# Query_time: 0.146976  Lock_time: 0.000106 Rows_sent: 10  Rows_examined: 450010
SET timestamp=1619316255;
select * from pp.pressure where id>450000 limit 10;
# Time: 2021-04-25T02:04:16.682978Z

慢日志中主要记录了：

  • 这条语句的执行时间。
  • 这条语句的内容。
  • 执行这条语句的客户端。
  • 语句的查询时间。
  • 锁定时间。
  • 返回了多少行。

analysis slow log

现在，这些慢语句已经被记录下来了，我们可以参考这个慢日志着手进行SQL优化。

但问题来了，如果这个日志中记录了很多很多日志，还有很多相同的日志，我们在着手优化时，就要分个轻重缓急了........

所以，我们需要对这些SQL语句分个优先级，哪些最影响性能、最影响用户体验的最优先解决，这时仅仅使用cat或者vim就不行了，而是需要使用相对专业的工具来帮助我们分析找出那些优先级高的SQL语句。

mysqldumpslow

mysqldumpslow是MySQL自带的慢日志分析工具：

[root@cs ~]# mysqldumpslow -s c -t 3 /logs/mysql_logs/slowlogs/slow.log 

Reading mysql slow query log from /logs/mysql_logs/slowlogs/slow.log
Count: 4  Time=1.65s (6s)  Lock=0.00s (0s)  Rows=1.0 (4), root[root]@localhost
  select count(*) from pp.pressure

Count: 4  Time=2.67s (10s)  Lock=0.00s (0s)  Rows=10.0 (40), root[root]@localhost
  select * from pp.pressure where id>N order by k1 limit N

Count: 4  Time=12.77s (51s)  Lock=0.00s (0s)  Rows=10.0 (40), root[root]@localhost
  select num from pp.pressure group by num limit N

由结果来看，mysqldumpslow工具会将记录的SQL语句进行分类，比如count(*)这类类似的语句归为一类等等....

mysqldumpslow有三个重要的参数：

  • -s表示以何种方式进行排序，可选参数有：
    • c表示按照查询次数进行排序，ac表示平均数。
    • t表示按照查询时间进行排序，at表示平均数。
    • l表示按照锁定时间进行排序，al表示平均数。
    • r表示返回的记录数进行排序，ar表示平均数。
  • -t表示top n的意思，表示返回结果集中的前n条慢日志记录。
  • -g表示正则，可以跟正则表达式，大小写不敏感。

示例：

-- 返回慢日志中记录的最多的前3条语句
mysqldumpslow -s r -t 3 /logs/mysql_logs/slowlogs/slow.log

-- 返回慢日志中记录的按照时间排序的前3条语句
mysqldumpslow -s t -t 3 /logs/mysql_logs/slowlogs/slow.log

-- 返回慢日志中记录的按照时间排序的前10条中包含left join的查询语句
mysqldumpslow -s t -t 10 -g "left join" /logs/mysql_logs/slowlogs/slow.log

除了MySQL自带的mysqldumpslow工具可以帮助我们分析慢日志，也可以使用第三方的一些分析工具，一起来看看。

pt-query-diagest

这里暂时不在多表，请参考：MySQL慢查询（二） - pt-query-digest详解慢查询日志

anemometer

这里暂时不在多表，请参考：https://blog.51cto.com/11257187/2119534

that's all,see also:

mysqldumpslow用法示例(慢查询) | MySQL慢查询分析mysqldumpslow | mySql的UDF是什么 | mysql的binlog日志的binlog_format模式与配置详解 |
老男孩-标杆班级-MySQL-lesson06-日志管理

posted @ 2021-04-25 10:27  听雨危楼  阅读(622)  评论(1)  编辑  收藏  举报