MySQL高级—17章(其他数据库日志)

MySQL高级部分
数据库
发布日期:   2024-01-24
更新日期:   2024-04-04
文章字数:   8.7k
阅读时长:   35 分
阅读次数:  

高级17章 其他数据库日志

我们在讲解数据库事务时，讲过两种日志：重做日志、回滚日志。

对于线上数据库应用系统，突然遭遇数据库宕机怎么办？在这种情况下，定位宕机的原因就非常关键。我们可以查看数据库的错误日志。因为日志中记录了数据库运行中的诊断信息，包括了错误、警告和注释等信息。比如：从日志中发现某个连接中的SQL操作发生了死循环，导致内存不足，被系统强行终止了。明确了原因，处理起来也就轻松了，系统很快就恢复了运行。

除了发现错误，日志在数据复制、数据恢复、操作审计，以及确保数据的永久性和一致性等方面，都有着不可替代的作用：

干万不要小看日志。很多看似奇怪的问题，答案往往就藏在日志里。很多情况下，只有通过查看日志才能发现问题的原因，真正解决问题。所以，一定要学会查看日志，养成检查日志的习惯，对提升你的数据库应用开发能力至关重要。

MySQL8.0 官网日志地址： https://dev.mysql.com/doc/refman/8.0/en/server-logs.html

1. MySQL支持的日志

1.1 日志类型

MySQL有不同类型的日志文件，用来存储不同类型的日志，分为 二进制日志 、 错误日志 、 通用查询日志和 慢查询日志 ，这也是常用的4种。MySQL 8又新增两种支持的日志： 中继日志 和 数据定义语句日志 。使用这些日志文件，可以查看MySQL内部发生的事情。

这6类日志分别为：

  • 慢查询日志：记录所有执行时间超过long_query_time的所有查询，方便我们对查询进行优化。
  • 通用查询日志：记录所有连接的起始时间和终止时间，以及连接发送给数据库服务器的所有指令，对我们复原操作的实际场景、发现问题，甚至是对数据库操作的审计都有很大的帮助。
  • 错误日志：记录MySQL服务的启动、运行或停止MySQL服务时出现的问题，方便我们了解服务器的状态，从而对服务器进行维护。
  • 二进制日志：记录所有更改数据的语句，可以用于主从服务器之间的数据同步，以及服务器遇到故障时数据的无损失恢复。
  • 中继日志：用于主从服务器架构中，从服务器用来存放主服务器二进制日志内容的一个中间文件。从服务器通过读取中继日志的内容，来同步主服务器上的操作。
  • 数据定义语句日志：记录数据定义语句执行的元数据操作。

除二进制日志外，其他日志都是 文本文件 。默认情况下，所有日志创建于 MySQL数据目录 中。

1.2 日志的弊端

  • 日志功能会 降低MySQL数据库的性能 。

    例如，在查询非常频繁的MySQL数据库系统中，如果开启了通用查询日志和慢查询日志，MySQL数据库会花费很多时间记录日志。

  • 日志会 占用大量的磁盘空间。

    对于用户量非常大、操作非常频繁的数据库，日志文件需要的存储空间设置比数据库文件需要的存储空间还要大。

2. 慢查询日志(slow query log)

前面章节《第09章_性能分析工具的使用》已经详细讲述。

3. 通用查询日志(general query log)

通用查询日志用来 记录用户的所有操作 ，包括启动和关闭MySQL服务、所有用户的连接开始时间和截止时间、发给 MySQL 数据库服务器的所有 SQL 指令等。当我们的数据发生异常时，查看通用查询日志，还原操作时的具体场景，可以帮助我们准确定位问题。

3.1 问题场景

在电商系统中，购买商品并且使用微信支付完成以后，却发现支付中心的记录并没有新增，此时用户再次使用支付宝支付，就会出现重复支付的问题。但是当去数据库中查询数据的时候，会发现只有一条记录存在。那么此时给到的现象就是只有一条支付记录，但是用户却支付了两次。

我们对系统进行了仔细检查，没有发现数据问题，因为用户编号和订单编号以及第三方流水号都是对的。可是用户确实支付了两次，这个时候，我们想到了检查通用查询日志，看看当天到底发生了什么。

查看之后，发现：1月1日下午2点，用户使用微信支付完以后，但是由于网络故障，支付中心没有及时收到微信支付的回调通知，导致当时没有写入数据。1月1日下午2点30，用户又使用支付宝支付，此时记录更新到支付中心。1月1日晚上9点，微信的回调通知过来了，但是支付中心已经存在了支付宝的记录，所以只能覆盖记录了。

由于网络的原因导致了重复支付。至于解决问题的方案就很多了，这里省略。

可以看到通用查询日志可以帮助我们了解操作发生的具体时间和操作的细节，对找出异常发生的原因极其关键。

3.2 查看当前状态

SHOW VARIABLES LIKE '%general%';

说明1：系统变量general_log的值是OFF，即通用查询日志处于关闭状态。在MySQL中，这个参数的默认值是关闭的。因为一旦开启记录通用查询日志，MySQL会记录所有的连接起止和相关的SQL操作，这样会消耗系统资源并且占用磁盘空间。我们可以通过手动修改变量的值，在需要的时候开启日志。

说明2：通用查询日志文件的名称是54fdeff0aeed.log。存储路径是/var/lib/mysql/，默认也是数据路径。这样我们就知道在哪里可以查看通用查询日志的内容了。

3.3 启动日志

方式1：永久性方式

修改my.cnf或者my.ini配置文件来设置。在[mysqld]组下加入log选项，并重启MySQL服务。格式如下：

mysqld]
general_log=ON
general_log_file=[path[filename]] #日志文件所在目录路径，filename为日志文件名

如果不指定目录和文件名，通用查询日志将默认存储在MySQL数据目录中的hostname.log文件中，hostname表示主机名。

方式2：临时性方式

SET GLOBAL general_log=on; # 开启通用查询日志

SET GLOBAL general_log_file=’path/filename’; # 设置日志文件保存位置

对应的，关闭操作SQL命令如下：

SET GLOBAL general_log=off; # 关闭通用查询日志

查看设置后情况：

SHOW VARIABLES LIKE 'general_log%';

3.4 查看日志

通用查询日志是以 文本文件 的形式存储在文件系统中的，可以使用 文本编辑器 直接打开日志文件。每台MySQL服务器的通用查询日志内容是不同的。

  • 在Windows操作系统中，使用文本文件查看器；
  • 在Linux系统中，可以使用vi工具或者gedit工具查看；
  • 在Mac OSX系统中，可以使用文本文件查看器或者vi等工具查看。

从 SHOW VARIABLES LIKE 'general_log%'; 结果中可以看到通用查询日志的位置。

刚刚上一小节才查看了：SHOW VARIABLES LIKE 'general_log%'；发现在/var/lib/mysql/54fdeff0aeed.log

在查看这个文件内容之前，我们先执行一些操作：

操作内容

查看通用日志文件信息

在通用查询日志里面，我们可以清楚地看到，什么时候开启了新的客户端登陆数据库，登录之后做了什么 SQL 操作，针对的是哪个数据表等信息。

3.5 停止日志

方式1：永久性方式

修改 my.cnf 或者 my.ini 文件，把[mysqld]组下的 general_log 值设置为 OFF 或者把general_log一项注释掉。修改保存后，再 重启MySQL服务 ，即可生效。 举例1：

[mysqld]
general_log=OFF

举例2：

[mysqld]
#general_log=ON

方式2：临时性方式

使用SET语句停止MySQL通用查询日志功能：

SET GLOBAL general_log=off;

查询通用日志功能：

SHOW VARIABLES LIKE 'general_log%';

3.6 删除\刷新日志

如果数据的使用非常频繁，那么通用查询日志会占用服务器非常大的磁盘空间。数据管理员可以删除很长时间之前的查询日志，以保证MySQL服务器上的硬盘空间。

手动删除文件

SHOW VARIABLES LIKE 'general_log%';

可以看出，通用查询日志的目录默认为MySQL数据目录。在该目录下手动删除通用查询日志54fdeff0aeed.log。

rm -rf 54fdeff0aeed.log

使用如下命令重新生成查询日志文件，具体命令如下。刷新MySQL数据目录，发现创建了新的日志文件。前提一定要开启通用日志。

mysqladmin -uroot -p flush-logs

可以发现又生成回来了

4. 错误日志(error log)

错误日志记录了MySQL服务器启动、停止运行的时间，以及系统启动、运行和停止过程中的诊断信息，包括错误、警告和提示等。

通过错误日志可以查看系统的运行状态，便于即时发现故障、修复故障。如果MySQL服务出现异常，错误日志是发现问题、解决故障的首选。

4.1 启动日志

在MySQL数据库中，错误日志功能是 默认开启 的。而且，错误日志 无法被禁止 。

默认情况下，错误日志存储在MySQL数据库的数据文件夹下，名称默认为 mysqld.log （Linux系统）或hostname.err （mac系统）。如果需要制定文件名，则需要在my.cnf或者my.ini中做如下配置：

[mysqld]
log-error=[path/[filename]] #path为日志文件所在的目录路径，filename为日志文件名

修改配置项后，需要重启MySQL服务以生效。

4.2 查看错误日志：

show variables like 'log_err%';

我这里是用的docker，所以可能会不一样

Docker中，MySQL的错误日志位置是相对于容器内部的。当show variables like 'log_err%';显示log_error为stderr时，表示错误日志输出到标准错误流（stderr）。在Docker容器中，默认情况下，stderr通常被重定向到容器的标准输出（stdout），也就是打印在控制台上。

4.3 删除\刷新日志

对于很久以前的错误日志，数据库管理员查看这些错误日志的可能性不大，可以将这些错误日志删除，以保证MySQL服务器上的 硬盘空间 。MySQL的错误日志是以文本文件的形式存储在文件系统中的，可以直接删除 。

  • 第1步（方式1）：删除操作

    rm -rf /var/lib/mysql/mysqld.log

    在运行状态下删除错误日志文件后，MySQL并不会自动创建日志文件。

  • 第1步（方式2）：重命名文件

    mv /var/lib/mysql/mysqld.log /var/lib/mysql/mysqld.log.old

  • 第2步：重建日志

    mysqladmin -uroot -p flush-logs

    可能会报错：

    [root@atguigu01 log]# mysqladmin -uroot -p flush-logs
Enter password:
mysqladmin: refresh failed; error: 'Could not open file '/var/log/mysqld.log' for
error logging.'

    官网提示：

    补充操作：

    install -omysql -gmysql -m0644 /dev/null /var/log/mysqld.log

5. 二进制日志(bin log)

binlog可以说是MySQL中比较 重要 的日志了，在日常开发及运维过程中，经常会遇到。

binlog即binary log，二进制日志文件，也叫作变更日志（update log）。它记录了数据库所有执行的DDL 和 DML 等数据库更新事件的语句，但是不包含没有修改任何数据的语句（如数据查询语句select、show等）。

它以事件形式记录并保存在二进制文件中。通过这些信息，我们可以再现数据更新操作的全过程。

如果想要记录所有语句（例如，为了识别有问题的查询），需要使用通用查询日志。

binlog主要应用场景：

  • 一是用于 数据恢复：如果MySQL数据库意外停止，可以通过二进制日志文件来查看用户执行了哪些操作对数据库服务器文件做了哪些修改，然后根据二进制日志文件中的记录来恢复数据库服务器。
  • 二是用于 数据复制：由于日志的延续性和时效性，master把它的二进制日志传递给slaves来达到master–slave数据一致的目的。

可以说MySQL数据库的数据备份、主备、主主、主从都离不开binlog，需要依靠binlog来同步数据，保证数据一致性。

5.1 查看默认情况

查看记录二进制日志是否开启：在MySQL8中默认情况下，二进制文件是开启的。

show variables like '%log_bin%';

  • log_bin_basename：是binlog日志的基本文件名，后面会追加标识来表示每一个文件
  • log_bin_index：是binlog文件的索引文件，这个文件管理了所有的binlog文件的目录
  • log_bin_trust_function_creators：限制存储过程，前面我们已经讲过了，这是因为二进制日志的一个重要功能是用于主从复制，而存储函数有可能导致主从的数据不一致。所以当开启二进制日志后，需要限制存储函数的创建、修改、调用
  • log_bin_use_v1_row_events：此只读系统变量已弃用。ON表示使用版本1二进制日志行，OFF表示使用版本2二进制日志行(MySQL5.6的默认值为2)。

5.2 日志参数设置

方式1：永久性方式

修改MySQL的 my.cnf 或 my.ini 文件可以设置二进制日志的相关参数：

默认是在/etc/mysql/目录下

[mysqld]
#启用二进制日志
log-bin=atguigu-bin
binlog_expire_logs_seconds=600
max_binlog_size=100M

提示：

  1. log-bin=mysql-bin#打开日志（主机需要打开），这个mysql-bin也可以自定义，这里也可以加上路径如：/home/www/mysql_bin_log/mysql-bin
  2. binlog_expire_logs_seconds：此参数控制二进制日志文件保留的时长，单位是秒，默认25920003天–144004小时；86400 1天；259200 3天；
  3. max_binlog_size：控制单个二进制日志大小，当前日志文件大小超过此变量时，执行切换动作。此参数的最大和默认值是1GB，该设置并不能严格控制Binlog的大小，尤其是Binlog比较靠近最大值而又遇到一个比较大事务时，为了保证事务的完整性，可能不做切换日志的动作，只能将该事务的所有SQL都记录进当前日志，直到事务结束。一般情况下可采取默认值。

修改

重新启动MySQL服务，查询二进制日志的信息，执行结果：

可以发现基本文件名和索引已经变了

这些文件每当我们重启MySQL的时候就会创建新的

设置带文件夹的bin-log日志存放目录

如果想改变日志文件的目录和名称，可以对my.cnf或my.ini中的log_bin参数修改如下：

[mysqld]
log-bin="/var/lib/mysql/binlog/atguigu-bin"

注意：新建的文件夹需要使用mysql用户，使用下面的命令即可。

chown -R -v mysql:mysql binlog

提示

数据库文件最好不要与日志文件放在同一个磁盘上！这样，当数据库文件所在的磁盘发生故障时，可以使用日志文件恢复数据。

方式2：临时性方式

如果不希望通过修改配置文件并重启的方式设置二进制日志的话，还可以使用如下指令，需要注意的是在mysql8中只有 会话级别 的设置，没有了global级别的设置。

set session sql_log_bin=0;
#或者
SET sql_log_bin=0;

5.3 查看日志

当MySQL创建二进制日志文件时，先创建一个以“filename”为名称、以“.index”为后缀的文件，再创建一个以“filename”为名称、以“.000001”为后缀的文件。

MySQL服务 重新启动一次 ，以“.000001”为后缀的文件就会增加一个，并且后缀名按1递增。即日志文件的个数与MySQL服务启动的次数相同；如果日志长度超过了 max_binlog_size 的上限（默认是1GB），就会创建一个新的日志文件。

查看当前的二进制日志文件列表及大小。指令如下：

SHOW BINARY LOGS;

现在我们执行如下名命令：

执行过程

开始查看binlog

mysqlbinlog "/var/lib/mysql/atguigu-bin.000001"
# The proper term is pseudo_replica_mode, but we use this compatibility alias
# to make the statement usable on server versions 8.0.24 and older.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#230717  6:09:53 server id 1  end_log_pos 125 CRC32 0x42a6e2f5  Start: binlog v 4, server v 8.0.27 created 230717  6:09:53 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
Mdu0ZA8BAAAAeQAAAH0AAAABAAQAOC4wLjI3AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAx27RkEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA
CigB9eKmQg==
'/*!*/;
# at 125
#230717  6:09:53 server id 1  end_log_pos 156 CRC32 0x903feac8  Previous-GTIDs
# [empty]
# at 156
#230717  6:39:46 server id 1  end_log_pos 235 CRC32 0x3b1965f2  Anonymous_GTID  last_committed=0        sequence_number=1       rbr_only=yes    original_committed_timestamp=1689575986828708  immediate_commit_timestamp=1689575986828708     transaction_length=339
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1689575986828708 (2023-07-17 06:39:46.828708 UTC)
# immediate_commit_timestamp=1689575986828708 (2023-07-17 06:39:46.828708 UTC)
/*!80001 SET @@session.original_commit_timestamp=1689575986828708*//*!*/;
/*!80014 SET @@session.original_server_version=80027*//*!*/;
/*!80014 SET @@session.immediate_server_version=80027*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 235
#230717  6:39:46 server id 1  end_log_pos 320 CRC32 0x0adf1eb3  Query   thread_id=8     exec_time=0     error_code=0
SET TIMESTAMP=1689575986/*!*/;
SET @@session.pseudo_thread_id=8/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 320
#230717  6:39:46 server id 1  end_log_pos 383 CRC32 0x2a338ed9  Table_map: `test1`.`student` mapped to number 90
# at 383
#230717  6:39:46 server id 1  end_log_pos 464 CRC32 0xaf5e3dce  Update_rows: table id 90 flags: STMT_END_F

BINLOG '
MuK0ZBMBAAAAPwAAAH8BAAAAAFoAAAAAAAEABXRlc3QxAAdzdHVkZW50AAUDAw8DAwI8ABwBAQAC
ASHZjjMq
MuK0ZB8BAAAAUQAAANABAAAAAFoAAAAAAAEAAgAF//8AAQk9AKKGAQAGd0xwcUp6LAAAAMQBAAAA
AQk9AKKGAQADVG9tLAAAAMQBAADOPV6v
'/*!*/;
# at 464
#230717  6:39:46 server id 1  end_log_pos 495 CRC32 0x797d4028  Xid = 14
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*/;

执行结果可以看到，这是一个简单的日志文件，日志中记录了用户的一些操作，这里并没有出现具体的SQL语句，这是因为binlog关键字后面的内容是经过编码后的二进制日志。

这里一个updatei语句包含如下事件

  • Query事件负责开始一个事务(BEGIN)
  • Table_map事件负责映射需要的表
  • Update_rows事件负责写入数据
  • Xid事件负责结束事务

以上4点组成一个事件。

下面命令将行事件以 伪SQL的形式 表现出来

mysqlbinlog -v "/var/lib/mysql/atguigu-bin.000001"
# The proper term is pseudo_replica_mode, but we use this compatibility alias
# to make the statement usable on server versions 8.0.24 and older.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#230717  6:09:53 server id 1  end_log_pos 125 CRC32 0x42a6e2f5  Start: binlog v 4, server v 8.0.27 created 230717  6:09:53 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
Mdu0ZA8BAAAAeQAAAH0AAAABAAQAOC4wLjI3AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAx27RkEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA
CigB9eKmQg==
'/*!*/;
# at 125
#230717  6:09:53 server id 1  end_log_pos 156 CRC32 0x903feac8  Previous-GTIDs
# [empty]
# at 156
#230717  6:39:46 server id 1  end_log_pos 235 CRC32 0x3b1965f2  Anonymous_GTID  last_committed=0        sequence_number=1       rbr_only=yes    original_committed_timestamp=1689575986828708  immediate_commit_timestamp=1689575986828708     transaction_length=339
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1689575986828708 (2023-07-17 06:39:46.828708 UTC)
# immediate_commit_timestamp=1689575986828708 (2023-07-17 06:39:46.828708 UTC)
/*!80001 SET @@session.original_commit_timestamp=1689575986828708*//*!*/;
/*!80014 SET @@session.original_server_version=80027*//*!*/;
/*!80014 SET @@session.immediate_server_version=80027*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 235
#230717  6:39:46 server id 1  end_log_pos 320 CRC32 0x0adf1eb3  Query   thread_id=8     exec_time=0     error_code=0
SET TIMESTAMP=1689575986/*!*/;
SET @@session.pseudo_thread_id=8/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 320
#230717  6:39:46 server id 1  end_log_pos 383 CRC32 0x2a338ed9  Table_map: `test1`.`student` mapped to number 90
# at 383
#230717  6:39:46 server id 1  end_log_pos 464 CRC32 0xaf5e3dce  Update_rows: table id 90 flags: STMT_END_F

BINLOG '
MuK0ZBMBAAAAPwAAAH8BAAAAAFoAAAAAAAEABXRlc3QxAAdzdHVkZW50AAUDAw8DAwI8ABwBAQAC
ASHZjjMq
MuK0ZB8BAAAAUQAAANABAAAAAFoAAAAAAAEAAgAF//8AAQk9AKKGAQAGd0xwcUp6LAAAAMQBAAAA
AQk9AKKGAQADVG9tLAAAAMQBAADOPV6v
'/*!*/;
### UPDATE `test1`.`student`
### WHERE
###   @1=4000001
###   @2=100002
###   @3='wLpqJz'
###   @4=44
###   @5=452
### SET
###   @1=4000001
###   @2=100002
###   @3='Tom'
###   @4=44
###   @5=452
# at 464
#230717  6:39:46 server id 1  end_log_pos 495 CRC32 0x797d4028  Xid = 14
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*/;

通过加上-v 参数，就可以看见里的伪SQL了。前面的语句同时也显示了binglog语句，使用如下命令可以不显示它：

mysqlbinlog -v --base64-output=DECODE-ROWS "/var/lib/mysql/atguigu-bin.000001"
# The proper term is pseudo_replica_mode, but we use this compatibility alias
# to make the statement usable on server versions 8.0.24 and older.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#230717  6:09:53 server id 1  end_log_pos 125 CRC32 0x42a6e2f5  Start: binlog v 4, server v 8.0.27 created 230717  6:09:53 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 125
#230717  6:09:53 server id 1  end_log_pos 156 CRC32 0x903feac8  Previous-GTIDs
# [empty]
# at 156
#230717  6:39:46 server id 1  end_log_pos 235 CRC32 0x3b1965f2  Anonymous_GTID  last_committed=0        sequence_number=1       rbr_only=yes    original_committed_timestamp=1689575986828708  immediate_commit_timestamp=1689575986828708     transaction_length=339
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1689575986828708 (2023-07-17 06:39:46.828708 UTC)
# immediate_commit_timestamp=1689575986828708 (2023-07-17 06:39:46.828708 UTC)
/*!80001 SET @@session.original_commit_timestamp=1689575986828708*//*!*/;
/*!80014 SET @@session.original_server_version=80027*//*!*/;
/*!80014 SET @@session.immediate_server_version=80027*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 235
#230717  6:39:46 server id 1  end_log_pos 320 CRC32 0x0adf1eb3  Query   thread_id=8     exec_time=0     error_code=0
SET TIMESTAMP=1689575986/*!*/;
SET @@session.pseudo_thread_id=8/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 320
#230717  6:39:46 server id 1  end_log_pos 383 CRC32 0x2a338ed9  Table_map: `test1`.`student` mapped to number 90
# at 383
#230717  6:39:46 server id 1  end_log_pos 464 CRC32 0xaf5e3dce  Update_rows: table id 90 flags: STMT_END_F
### UPDATE `test1`.`student`
### WHERE
###   @1=4000001
###   @2=100002
###   @3='wLpqJz'
###   @4=44
###   @5=452
### SET
###   @1=4000001
###   @2=100002
###   @3='Tom'
###   @4=44
###   @5=452
# at 464
#230717  6:39:46 server id 1  end_log_pos 495 CRC32 0x797d4028  Xid = 14
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*/;

关于mysqlbinlog工具的使用技巧还有很多，例如只解析对某个库的操作或者某个时间段内的操作等。简单分享几个常用的语句，更多操作可以参考官方文档。

# 可查看参数帮助
mysqlbinlog --no-defaults --help

# 查看最后100行
mysqlbinlog --no-defaults --base64-output=decode-rows -vv atguigu-bin.000002 |tail -100
# 根据position查找
mysqlbinlog --no-defaults --base64-output=decode-rows -vv atguigu-bin.000002 |grep -A 20 '4939002'

上面这种办法读取出binlog日志的全文内容比较多，不容易分辨查看到pos点信息，下面介绍一种更为方便的查询命令：

 show binlog events [IN 'log_name'] [FROM pos] [LIMIT [offset,] row_count];

  • IN 'log_-name'：指定要查询的binlog文件名(不指定就是第一个binlog文件)

  • FROM pos ：指定从哪个pos起始点开始查起（不指定就是从整个文件首个pos点开始算）

  • LIMIT [offset] ：偏移量(不指定就是0)

  • row_count :查询总条数（不指定就是所有行）

show binlog events in 'atguigu-bin.000001';

上面这条语句可以将指定的binlog日志文件，分成有效事件行的方式返回，并可使用limit指定pos点的起始偏移，查询条数。

其它举例：

#查看第一个最早的binlog日志：
show binlog events\G;

mysql> show binlog events\G;
*************************** 1. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 125
       Info: Server ver: 8.0.27, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 125
 Event_type: Previous_gtids
  Server_id: 1
End_log_pos: 156
       Info: 
*************************** 3. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 156
 Event_type: Anonymous_Gtid
  Server_id: 1
End_log_pos: 235
       Info: SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
*************************** 4. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 235
 Event_type: Query
  Server_id: 1
End_log_pos: 320
       Info: BEGIN
*************************** 5. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 320
 Event_type: Table_map
  Server_id: 1
End_log_pos: 383
       Info: table_id: 90 (test1.student)
*************************** 6. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 383
 Event_type: Update_rows
  Server_id: 1
End_log_pos: 464
       Info: table_id: 90 flags: STMT_END_F
*************************** 7. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 464
 Event_type: Xid
  Server_id: 1
End_log_pos: 495
       Info: COMMIT /* xid=14 */
7 rows in set (0.00 sec)

#查看指定mysql-bin.000001这个文件
show binlog events in 'atguigu-bin.000001'\G;

mysql> show binlog events in 'atguigu-bin.000001'\G;
*************************** 1. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 125
       Info: Server ver: 8.0.27, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 125
 Event_type: Previous_gtids
  Server_id: 1
End_log_pos: 156
       Info: 
*************************** 3. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 156
 Event_type: Anonymous_Gtid
  Server_id: 1
End_log_pos: 235
       Info: SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
*************************** 4. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 235
 Event_type: Query
  Server_id: 1
End_log_pos: 320
       Info: BEGIN
*************************** 5. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 320
 Event_type: Table_map
  Server_id: 1
End_log_pos: 383
       Info: table_id: 90 (test1.student)
*************************** 6. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 383
 Event_type: Update_rows
  Server_id: 1
End_log_pos: 464
       Info: table_id: 90 flags: STMT_END_F
*************************** 7. row ***************************
   Log_name: atguigu-bin.000001
        Pos: 464
 Event_type: Xid
  Server_id: 1
End_log_pos: 495
       Info: COMMIT /* xid=14 */
7 rows in set (0.00 sec)

等待还有很多，这里就不一一举例了。

上面我们讲了这么多都是基于binlog的默认格式，binlog格式查看

show variables like 'binlog_format';

除此之外，binlog还有2种格式，分别是Statement和Mixed

  • Statement
    每一条会修改数据的sql都会记录在binlog中。
    优点：不需要记录每一行的变化，减少了binlog日志量，节约了IO，提高性能。
  • Row
    5.1.5版本的MySQL才开始支持row level 的复制，它不记录sql语句上下文相关信息，仅保存哪条记录被修改。
    优点：row level 的日志内容会非常清楚的记录下每一行数据修改的细节。而且不会出现某些特定情况下的存储过程，或function，以及trigger的调用和触发无法被正确复制的问题。
  • Mixed
    从5.1.8版本开始，MySQL提供了Mixed格式，实际上就是Statement与Row的结合。详细情况，下章讲解。

5.4 使用日志恢复数据

如果MySQL服务器启用了二进制日志，在数据库出现意外丢失数据时，可以使用MySQLbinlog工具从指定的时间点开始（例如，最后一次备份）直到现在或另一个指定的时间点的日志中恢复数据。

mysqlbinlog恢复数据的语法如下：

mysqlbinlog [option] filename|mysql –uuser -ppass;

这个命令可以这样理解：使用mysqlbinlog命令来读取filename中的内容，然后使用mysql命令将这些内容恢复到数据库中。

  • filename ：是日志文件名。
  • option ：可选项，比较重要的两对option参数是–start-date、–stop-date 和 –start-position、–stop-position。
    • –start-date 和 –stop-date ：可以指定恢复数据库的起始时间点和结束时间点。
    • –start-position和–stop-position ：可以指定恢复数据的开始位置和结束位置。

注意：使用mysqlbinlog命令进行恢复操作时，必须是编号小的先恢复，例如atguigu-bin.000001必须在atguigu-bin.000002之前恢复。

详细例子：

操作数据之前先记录一下文件大小

查看操作之前的数据

修改数据

删除数据

好，在我经过一顿操作之后，id为400001的数据被删除了，id为400002的数据的name被改为了jerry，现在我要恢复数据。有两种方式，一种是用定位到pos点来恢复，另外一种使用时间来恢复，我这里只演示第一种。

在恢复数据之前，先查看日志文件的大小和数据：

发现相对于操作之前查看的大小要大

show binlog events in 'atguigu-bin.000001';

Flush logs 刷新日志，此刻开始产生一个新编号的binlog文件

建议在恢复的时候使新的日志文件。

执行恢复操作：

/usr/bin/mysqlbinlog --start-position=起始pos --stop-position=结束pos /var/lib/mysql/日志文件 | mysql -uroot -p密码

5.5 删除二进制日志

MySQL的二进制文件可以配置自动删除，同时MySQL也提供了安全的手动删除二进制文件的方法。

PURGE MASTER LOGS 只删除指定部分之前的二进制日志文件， RESET MASTER 删除所有的二进制日志文件。具体如下：

  1. PURGE MASTER LOGS：删除指定日志文件之前的文件

    PURGE MASTER LOGS语法如下：

    PURGE {MASTER | BINARY} LOGS TO ‘指定日志文件名’
PURGE {MASTER | BINARY} LOGS BEFORE ‘指定日期’

    举例：

    我这里有这些日志文件：

    先我想要删除000006之前的日志文件：

    purge master logs to 'binlog.000006';

    可见删除了指定日志文件之前的所有文件

  2. RESET MASTER：删除所有二进制日志文件

    使用RESET MASTER语句，清空所有的binlog日志。MySQL会重新创建二进制文件，新的日志文件扩展名将重新从000001开始编号。慎用！

    执行结果

5.6 其它场景

二进制日志可以通过数据库的 全量备份 和二进制日志中保存的 增量信息 ，完成数据库的 无损失恢复 。但是，如果遇到数据量大、数据库和数据表很多（比如分库分表的应用）的场景，用二进制日志进行数据恢复，是很有挑战性的，因为起止位置不容易管理。

在这种情况下，一个有效的解决办法是 配置主从数据库服务器 ，甚至是 一主多从 的架构，把二进制日志文件的内容通过中继日志，同步到从数据库服务器中，这样就可以有效避免数据库故障导致的数据异常等问题。

6. 再谈二进制日志(binlog)

6.1 写入机制

binlog的写入时机也非常简单，事务执行过程中，先把日志写到 binlog cache ，事务提交的时候，再把binlog cache写到binlog文件中。因为一个事务的binlog不能被拆开，无论这个事务多大，也要确保一次性写入，所以系统会给每个线程分配一个块内存作为binlog cache。

我们可以通过binlog_cache_size参数控制单个线程binlog cache大小，如果存储内容超过了这个参数，就要暂存到磁盘(Swap)。binlog日志刷盘流程如下：

  • 上图的write，是指把日志写入到文件系统的page cache，并没有把数据持久化到磁盘，所以速度比较快。
  • 上图的fsync,才是将数据持久化到磁盘的操作。

write和fsync的时机，可以由参数 sync_binlog 控制，默认是 0 。为0的时候，表示每次提交事务都只write，由系统自行判断什么时候执行fsync。虽然性能得到提升，但是机器宕机，page cache里面的binglog 会丢失。如下图：

为了安全起见，可以设置为 1 ，表示每次提交事务都会执行fsync，就如同redo log 刷盘流程一样。最后还有一种折中方式，可以设置为N(N>1)，表示每次提交事务都write，但累积N个事务后才fsync。

在出现IO瓶颈的场景里，将sync_binlog设置成一个比较大的值，可以提升性能。同样的，如果机器宕机，会丢失最近N个事务的binlog日志。

6.2 binlog与redolog对比

  • redo log 它是 物理日志 ，记录内容是“在某个数据页上做了什么修改”，属于 InnoDB 存储引擎层产生的。

  • 而 binlog 是 逻辑日志 ，记录内容是语句的原始逻辑，类似于“给 ID=2 这一行的 c 字段加 1”，属于MySQL Server 层。

  • 虽然它们都属于持久化的保证，但是则重点不同。

    • redo log让InnoDB存储引擎拥有了崩溃恢复能力。
    • binlog保证了MySQL集群架构的数据一致性。

6.3 两阶段提交

在执行更新语句过程，会记录redo log与binlog两块日志，以基本的事务为单位，redo log在事务执行过程中可以不断写入，而binlog只有在提交事务时才写入，所以redo log与binlog的 写入时机 不一样。

redo log与binlog两份日志之间的逻辑不一致，会出现什么问题？

以update语句为例，假设id=2的记录，字段c值是0，把字段c值更新成1，SQL语句为update T set c=1 where id=2。假设执行过程中写完redo log日志后，binlog日志写期间发生了异常，会出现什么情况呢？

由于binlog没写完就异常，这时候binlog里面没有对应的修改记录。因此，之后用binlog日志恢复数据时，就会少这一次更新，恢复出来的这一行c值是0，而原库因为redo log日志恢复，这一行c值是1，最终数据不一致。

为了解决两份日志之间的逻辑一致问题，InnoDB存储引擎使用两阶段提交方案。原理很简单，将redo log的写入拆成了两个步骤prepare和commit,这就是两阶段提交。

使用两阶段提交后，写入binlog时发生异常也不会有影响，因为MySQL根据redo log日志恢复数据时，发现redo log还处于preparel阶段，并且没有对应binlog日志，就会回滚该事务。

另一个场景，redo log设置commit阶段发生异常，那会不会回滚事务呢？

并不会回滚事务，它会执行上图框住的逻辑，虽然redo log是处于prepare阶段，但是能通过事务id找到对应的binlog日志，所以MySQL认为是完整的，就会提交事务恢复数据。

7. 中继日志(relay log)

7.1 介绍

中继日志只在主从服务器架构的从服务器上存在。从服务器为了与主服务器保持一致，要从主服务器读取二进制日志的内容，并且把读取到的信息写入 本地的日志文件 中，这个从服务器本地的日志文件就叫中继日志 。然后，从服务器读取中继日志，并根据中继日志的内容对从服务器的数据进行更新，完成主
从服务器的 数据同步 。

搭建好主从服务器之后，中继日志默认会保存在从服务器的数据目录下。

文件名的格式是： 从服务器名 -relay-bin.序号 。中继日志还有一个索引文件： 从服务器名 -relay-bin.index ，用来定位当前正在使用的中继日志。

7.2 查看中继日志

中继日志与二进制日志的格式相同，可以用 mysqlbinlog 工具进行查看。下面是中继日志的一个片段：

SET TIMESTAMP=1618558728/*!*/;
BEGIN
/*!*/;
# at 950
#210416 15:38:48 server id 1 end_log_pos 832 CRC32 0xcc16d651 Table_map:
`atguigu`.`test` mapped to number 91
# at 1000
#210416 15:38:48 server id 1 end_log_pos 872 CRC32 0x07e4047c Delete_rows: table id
91 flags: STMT_END_F -- server id 1 是主服务器，意思是主服务器删了一行数据
BINLOG '
CD95YBMBAAAAMgAAAEADAAAAAFsAAAAAAAEABGRlbW8ABHRlc3QAAQMAAQEBAFHWFsw=
CD95YCABAAAAKAAAAGgDAAAAAFsAAAAAAAEAAgAB/wABAAAAfATkBw==
'/*!*/;
# at 1040

这一段的意思是，主服务器（“server id 1”）对表 atguigu.test 进行了 2 步操作：

定位到表 atguigu.test 编号是 91 的记录，日志位置是 832；
删除编号是 91 的记录，日志位置是 872。

7.3 恢复的典型错误

如果从服务器宕机，有的时候为了系统恢复，要重装操作系统，这样就可能会导致你的 服务器名称 与之前 不同 。而中继日志里是 包含从服务器名 的。在这种情况下，就可能导致你恢复从服务器的时候，无法从宕机前的中继日志里读取数据，以为是日志文件损坏了，其实是名称不对了。

解决的方法也很简单，把从服务器的名称改回之前的名称。

文章作者: 念心卓
文章链接: http://blog.cqwulyj.cn/posts/2bc561b2.html
版权声明: 本博客所有文章除特別声明外，均采用 CC BY 4.0 许可协议。转载请注明来源 念心卓 !
MySQL高级部分
  目录