Loading

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很大,我们还可以通过limitfrom过滤结果:

-- 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  听雨危楼  阅读(128)  评论(1编辑  收藏  举报