MySQL 日志相关

2021-05-19 database mysql

MySQL 中的日志主要包括了:错误日志、查询日志、慢查询日志、事务日志、二进制日志,在此,介绍下一些常见的配置,以及 BinLog 相关内容。

简介

MySQL 的日志子系统主要包括 error logbinloggeneral log 三种类型的日志,可以通过如下命令查看与日志相关的配置参数。

mysql> SHOW GLOBAL VARIABLES LIKE '%log%';

错误日志 (error log)

默认情况下错误日志大概记录以下几个方面的信息:

  • 服务器启动和关闭过程中的信息;
  • 服务器运行过程中的错误信息;
  • 事件调度器运行一个事件时产生的信息;
  • 在从服务器上启动服务器进程时产生的信息。
[mysqld]
log_error    = localhost.err      # 使用datadir相对路径,如果没有err后缀会自动添加
log_error    = /PAHT/TO/LOG/      # 指定绝对路径,默认是hostname.err,主机名可以为空
log_warnings = 1                  # 是否将警告信息记录进错误日志,0(禁用),1(启用)
                                  #  >1(建新连接时产生的"失败的连接"和"拒绝访问"类的错误信息)

设置完后,可通过 SHOW VARIABLES LIKE 'log_error' 查看具体路径;在 5.5.7 前,可以通过 FLUSH LOGS 保存老的日志,并开辟新的日志文件;之后只能 mv 之后再 FLUSH LOGS

mysql> flush logs;
$ mysqladmin flush-logs
$ mysqladmin refresh

查询日志 (general log)

记录了客户端的连接、关闭、发送的 SQL 请求,当怀疑客户端有问题,且想查看客户端发送的 SQL 请求时可以打开该日志;线上不建议使用。

[mysqld]
general_log      = OFF            # 是否开启一般查询日志
log_output       = FILE           # 日志输出对象,FILE(文件),TALBE(表),NONE(不记录)
general_log_file = hostname.log   # 查询日志文件名

慢查询日志 (slow qurey log)

用来记录慢查询,当超过了 long_query_time 指定的时间之后,会输出到 slow_query_log_file 指定的文件中。这里的语句执行时长为实际的执行时间,而非在 CPU 上的执行时长,对于负载较重的服务器上更容易产生慢查询。

slow_query_log                = OFF           # 是否记录超过long_query_time时间的慢查询
log_output                    = FILE          # 同上,可作用于查询日志和慢查询日志
                                              # 如果是TABLE,会在mysql库下生成general_log和slow_log
slow_query_log_file           = slow.log      # 设定文件格式的慢查询日志的存储路径
long_query_time               = 10.000000     # 区别慢查询与一般查询的语句执行时间长度
log_queries_not_using_indexes = ON            # 记录没有使用索引的SQL
log_slow_admin_statements     = ON            # 记录表管理语句
log_slow_slave_statements     = ON            # 记录主备复制时,超时的SQL
expire_logs_days              = 0             # 超出此天数的二进制日志文件将被自动删除
min_examined_row_limit        = 100           # 查询检查返回少于该参数指定行的SQL不被记录到慢查询日志
log_throttle_queries_not_using_indexes = 0    # 每分钟允许记录到slow log的且未使用索引的SQL语句次数

对于慢查询日志,可以通过 MySQL 自带的 mysqldumpslow 命令行查看。

二进制日志 (binary log)

log_bin                       = mysql-bin       # 启用二进制日志记录功能,静态变量(设置需重启)
log_bin_index                 = mysql-bin.index # 二进制索引文件的路径与名称
binlog-format                 = ROW             # binlog的记录格式,包括ROW|STATEMENT|MIXED三种
sync_binlog                   = 1               # 日志缓存刷新时机,详见下面介绍
max_binlog_size               = 1073741824      # 指定单个二进制日志文件的最大值,默认1GB
log_slave_updates             = OFF             # (备库)是否将接收到的记录到本地binlog,用于级联复制
expire_logs_days              = 3               # 实现自动删除binlog,保留3天
binlog_cache_size             = 1M              # 为每个会话分配的binlog内存大小
max_binlog_cache_size         = 184467440737    # 设置binlog最大可用内存

注意,max_binlog_size 并不能严格控制 Binlog 的大小,尤其是 Binlog 比较靠近最大值而又遇到一个比较大事务时,为了保证事务的完整性,不可能做切换日志的动作,只能将该事务的所有 SQL 都记录进当前日志,直到事务结束

中继日志 (relay log)

relay_log                 = relay-log          # 开启中继日志
relay_log_index           = relay-log.index    # 中继日志索引文件的名称
relay_log_info_repository = FILE               # 中继日志位置写入对象,FILE(文件) TABLE(表slave_relay_log_info)
relay_log_info_file       = relay-log.info     # 记录中继日志的文件和事件位置以及二进制的文件和事件位置

relay_log_recovery            = ON             # (备库)relaylog自动修复,避免网络等造成损坏,导致主从停止
relay_log_purge               = ON             # (备库)启动自动清除中继日志
master_info_repository        = TABLE          # (备库)保存主机相关信息master.info(FILE)
                                               #       slave_master_info(TABLE)
relay_log_info_repository     = TABLE          # (备库)记录relaylog相关信息relay-log.info(FILE)
                                               #       slave_relay_log_info(TABLE)
log_slave_updates             = OFF            # (备库)是否将接收到的记录到本地binlog,用于级联复制

对于 relay_log_recovery 参数,当 slave 从库宕机后,假如 relay-log 损坏,会导致一部分中继日志没有处理,则自动放弃所有未执行的 relay-log,并且重新从 master 上获取日志,从而保证 relay-log 的完整性。

Binlog

这个是比较重要的日志,该日志用于记录所有更新了数据的所有语句,可以用于实时备份,或者 master/slave 复制,如果要打开该功能需要重启。

[mysqld]
log-bin=mysql-bin
binlog_format=mixed

对于过期不需要的 binlog,为了节省空间,可以手工删除或自动删除,相关的 SQL 命令有。

----- 常用操作
mysql> SET sql_log_bin=ON;                             ← 启用(ON)或禁用(OFF)当前会话的binlog记录
mysql> SET GLOBAL expire_logs_days = 10;               ← 设置binlog过期时间
mysql> SHOW BINARY LOGS;                               ← 查找当前有哪些二进制日志文件
mysql> SHOW BINLOG EVENTS IN 'mysql-bin.000001';       ← 查看日志详细信息
mysql> FLUSH LOGS;                                     ← 切换到新的binlog

mysql> SHOW MASTER LOGS;                               ← 同上,查看master的binlog日志
mysql> SHOW MASTER STATUS;                             ← 查看master二进制日志文件的状态信息
mysql> SHOW SLAVE HOSTS;                               ← 显示当前注册的slave的列表
                                                       ← 需要--report-host参数指定

----- 日志手动清理,可以指定master/binary
mysql> RESET MASTER;                                   ← 删除master的binlog
mysql> RESET SLAVE;                                    ← 删除slave的中继日志
mysql> PURGE MASTER LOGS BEFORE '2012-03-30 17:20:00'; ← 指定日期删除
mysql> PURGE BINARY LOGS TO 'mysql-bin.000018';        ← 指定文件删除
mysql> PURGE MASTER LOGS BEFORE DATE_SUB( NOW( ), INTERVAL 3 DAY);

$ mysqlbinlog mysql-bin.000003  | less                 ← 查看日志文件的内容
$ mysqlbinlog --start-datetime='2015-08-05 00:00:00' --stop-datetime='2015-08-05 10:00:00' \
    --database=db_name mysql-bin.000001
$ mysqlbinlog --start-postion=107 --stop-position=1000 --database=db_name mysql-bin.000001
----- 从远程服务器读取
$ mysqlbinlog -u username -p password -h127.1 -P3306 --read-from-remote-server \
    --start-datetime='2015-08-05 00:00:00' --stop-datetime='2015-08-05 10:00:00' mysql-bin.000001
$ mysqlbinlog --base64-output=decode-rows mysql-bin.000003

其中,与之相关的文件有 mysql-bin.NUMmysql-bin.index;后者以文本格式保留了未被 purge 的 binlog 文件;前者为真正的 binlog 文件,以二进制形式存在,可以通过 mysqlbinlog 读取。

配置

对于 binlog 的配置项可以参考如下,只列举了部分常用的。

cache

会为每个 session 分配 binlog_cache_size 大小的内存,在事务过程中用来保存 binlog 缓存;如果没有大事务,DML 操作不频繁,那么可以适当的调小一点。

max_binlog_cache_size            # 设置binlog最大可用内存
binlog_cache_size     = 1M       # 为每个会话分配的binlog内存大小

上述参数可通过状态 binlog_cache_usebinlog_cache_disk_use 来帮助设置合理的区间值。

binlog_cache_use
    使用缓存binlog的次数
binlog_cache_disk_use
    超过binlog_cache_size值,导致缓存不足,从而使用临时文件来保存事务的次数

binlog_cache_disk_use 比较大时,可以考虑适当的调高 binlog_cache_size 对应的值;当执行多语句的事务时,如果所有会话使用的内存超过 max_binlog_cache_size 的值时,会报如下错误:

Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage;
increase this mysqld variable and try again

磁盘刷新

可以通过 sync_binlog 参数设置刷盘的时机,该值将直接影响 MySQL 的性能和日志的完整性。

  • sync_binlog=0 事务提交后,仅是将 binlog_cache 中的数据写入 Binlog 文件,但不执行 fsync 之类的磁盘同步操作通知文件系统将缓存刷新到磁盘,而让文件系统自行决定什么时候来做同步,此时性能最好。
  • sync_binlog=N 在执行了 N 次事务提交后,MySQL 将执行一次 fsync 之类的磁盘同步指令,此时文件系统将 Binlog 文件缓存刷新到磁盘。

默认值是 0,即不作任何强制性的磁盘刷新指令,这时性能是最好的,但风险也是最大的;一旦系统 Crash,在文件系统缓存中的所有 Binlog 信息都会丢失。

文件格式

有三种格式,也对应了 MySQL 的复制技术,分别是:基于SQL语句的复制 (Statement-Based Replication, SBR),基于行的复制 (Row-Based Replication, RBR),混合模式复制 (Mixed-Based Replication, MBR)。

可以通过如下 SQL 查看当前 binlog 的格式,包括了三种:STATEMENTROWMIXED;默认采用的是 MIXED

mysql> SHOW VARIABLES LIKE 'binlog_format';        ← 查看binlog格式
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | MIXED |
+---------------+-------+
1 row in set (0.01 sec)

mysql> SET GLOBAL binlog_format = 'STATEMENT';     ← 设置格式,还可以为ROW,MIXED
Query OK, 0 rows affected (0.03 sec)

mysql> FLUSH LOGS;                                 ← 切换日志
Query OK, 0 rows affected (0.03 sec)

mysql> SHOW BINARY LOGS;                           ← 查看binlog日志
+-----------------+-----------+
| Log_name        | File_size |
+-----------------+-----------+
| mysql-bin.000001|       409 |
| mysql-bin.000002|       346 |
+-----------------+-----------+
2 rows in set (0.00 sec)

mysql> SHOW BINLOG EVENTS;                         ← 查看执行的SQL
mysql> SHOW BINLOG EVENTS IN 'mysql-bin.000002';   ← 查看指定binlog文件的内容
mysql> SHOW BINLOG EVENTS FROM 213;                ← 指定位置binlog的内容

下面简单介绍上述的不同 binlog 日志格式。

Statement

MySQL 5.0 之前仅支持基于语句的复制,也叫做逻辑复制 (Logical Replication);主会记录下执行的 SQL,然后,备从中继日志中读取事件,并执行它,这些 SQL 语句与主执行的语句一样。

优点:
    最先实现,技术比较成熟;
    可以方便的显示SQL语句,日志可用于安全审计;
    DDL语句总是被记录成statement,即便你设置的是row模式;
    生成文件较小;
    事件类型是:0x02(Query_log_event);
    方便mysqlbinlog处理;
    主从版本可以不一样,从服务器版本可以比主服务器版本高;

缺点:
    部分UPDATE语句无法复制,尤其是包含不确定操作的时候,如RAND();
    一些元数据信息,存储过程和触发器等就可能会出错;
    使用以下函数的语句也无法被复制,也就是Unsafe/non-deterministic statements:
        * User-defined functions (UDF)
        * UUID(), FOUND_ROWS(), RAND(), USER(), LOAD_FILE()
        * Updates using LIMIT
        * SYSDATE() (除非启动时启用了 --sysdate-is-now 选项)
    数据表必须和主服务器保持一致,否则可能会导致复制出错;

另外,基于语句的复制必须是串行化的,从而导致大量特殊的代码、配置等。

Row

在 5.1 之后被引入,该方式会在二进制日志中记录下实际数据的改变,优点就是可以对任何语句都能正确工作,一些语句的效率更高;主要的缺点就是二进制日志可能会很大,而且不直观。

优点:
    对于非确定性函数:UUID等,都是安全的;
    事件类型为 Table_map, Write_rows, Update_rows, Delete_rows
    任何情况都可以被复制,这对复制来说是最安全可靠的;
    执行 INSERT,UPDATE,DELETE 语句时锁更少;
    从服务器上采用多线程来执行复制成为可能;

缺点:
    文件大了很多,尤其是一条语句更新全表的情况;
    只有DML语句才能记录成row模式;
    无法从binlog查看复制语句;

Mixed

前两者的结合,默认以 statment 格式记录,当遇到 non-deterministic statements 语句时,自动转换成 row 模式。

总结

对于 INSERT,UPDATE,DELETE 之类的直接操作表的情况,则日志格式根据 binlog_format 的设定而记录;而对于 GRANT,REVOKE,SET PASSWORD 等语句来说,均采用 SBR 模式记录。

Binlog 解析

其中 mysql-bin.index 没什么需要详细解释的;下面,着重看下二进制 binlog 文件,文件格式有以下特点:

  • binlogevent 组成,eventbinlog 的最小逻辑单元;
  • 文件头的头四个字节为固定的 BINLOG_MAGIC (fe 62 69 6e),后三个为 ASCII 码的 bin
  • 接着的四字节是 descriptor event (FORMAT_DESCRIPTION_EVENT),记录了版本信息等;
  • 文件末尾是 log-rotation event (ROTATE_EVENT),记录了下个 binlog 文件名;
  • 上述两个 event 中间是各种不同的 event,每个 event 代表数据库中不同的操作。

对于 binlog 可以直接利用 hexdump -C 命令读取 mysql-bin.NNNNNN 文件的内容;当然,也可以通过 mysqlbinlog --hexdump 命令查看;其中示例如下。

$ hexdump -C mysql-bin.000001
00000000  fe 62 69 6e ca f0 78 58  0f ea 0c 00 00 77 00 00  |.bin..xX.....w..|
00000010  00 7b 00 00 00 00 00 04  00 35 2e 37 2e 31 36 2d  |.{.......5.7.16-|
00000020  64 65 62 75 67 2d 6c 6f  67 00 00 00 00 00 00 00  |debug-log.......|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000040  00 00 00 00 00 00 00 00  00 00 00 ca f0 78 58 13  |.............xX.|
00000050  38 0d 00 08 00 12 00 04  04 04 04 12 00 00 5f 00  |8............._.|
00000060  04 1a 08 00 00 00 08 08  08 02 00 00 00 0a 0a 0a  |................|
00000070  2a 2a 00 12 34 00 01 e8  74 31 a6 ca f0 78 58 23  |**..4...t1...xX#|
00000080  ea 0c 00 00 1f 00 00 00  9a 00 00 00 80 00 00 00  |................|
00000090  00 00 00 00 00 00 a5 0a  43 ae 10 f3 78 58 04 ea  |........C...xX..|
000000a0  0c 00 00 2f 00 00 00 c9  00 00 00 00 00 04 00 00  |.../............|
000000b0  00 00 00 00 00 6d 79 73  71 6c 2d 62 69 6e 2e 30  |.....mysql-bin.0|
000000c0  30 30 30 30 32 f4 b1 f2  56                       |00002...V|
000000c9

在开始+结尾的两个事件中间,是各种其他的 event 。

实例解析

接下来,看看执行如下 SQLs 所生成的不同格式的 binlog 。

FLUSH LOGS;
USE test;
DROP TABLE foobar;
CREATE TABLE foobar (id INT PRIMARY KEY, name VARCHAR(20), gmt_create TIMESTAMP);
INSERT INTO foobar VALUES(1, "Andy", NOW()), (2, "Carter", NOW());
UPDATE foobar SET name = "Devin" WHERE id = 1;
DELETE FROM foobar WHERE id = 1;
FLUSH LOGS;

可以通过 mysqlbinlog 解析 binlog 日志,其中内容可以参考如下。

######################### Statement-Based Replication, SBR
# at 979
#150809 20:52:54 server id 1 end_log_pos 1126 CRC32 0x1044160e Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1486817574/*!*/;
INSERT INTO foobar VALUES(1, "Andy", NOW()), (2, "Carter", NOW())

######################### Row-Based Replication, RBR
/*!*/;
# at 1765
#170211 21:23:05 server id 1 end_log_pos 1819 CRC32 0xd5c8e00d Table_map: `test`.`foobar` mapped to number 108
# at 1819
#170211 21:23:05 server id 1 end_log_pos 1884 CRC32 0x2e610487 Update_rows: table id 108 flags: STMT_END_F
BINLOG '
ORCfWBMBAAAANgAAABsHAAAAAGwAAAAAAAEABHRlc3QABmZvb2JhcgADAw8RAxQAAAIN4MjV
ORCfWB8BAAAAQQAAAFwHAAAAAGwAAAAAAAEAAgAD///4AQAAAARBbmR5WJ8QLPgBAAAABURldmlu
WJ8QOYcEYS4=
'

详细介绍:
  * 位于文件中的位置
    "at 979" 为事件的起点,从第196字节开始;"end_log_pos 1126"说明以第1126字节处结束;
  * 时间戳
    事件发生的时间"150809 20:52:54"
  * 服务器的标识
    服务器的标识id "server id 1",可以在配置文件中通过server-id参数设置
  * 事件执行时间
    事件执行花费的时间"exec_time=0"
  * 错误码
    该事件执行的错误码为"error_code=0"

二进制解析

仍然是上述的示例,首先可以查看下关于 MySQL Internals Manual – Binlog Event 中的介绍,主要是关于 event 格式的介绍。

Binlog Event header

头部信息通常是在每个事件的开始,根据版本不同一般为 13/19 字节,只要版本大于 1 均为 19 字节,其头部的格式如下:

字节数   解析
4        1970.1.1以来的秒数,小端存储
1        事件类型,通过enum Log_event_type定义
4        服务器ID,在配置文件中通过server-id指定,用于循环复制过滤事件
4        整个事件的大小,包括了头部+事件体等
4        下个事件的偏移量
2        flags,通过类似LOG_EVENT_XXX_F宏定义,例如LOG_EVENT_ARTIFICIAL_F

接下来就是事件体了,不同的事件显然定义不同,关于具体的格式可以参考 Binlog Event .

实例解析

$ hexdump mysql-bin.000024 -C -n 100
00000000  fe 62 69 6e 57 7f ad 58  0f ea 0c 00 00 77 00 00  |.binW..X.....w..|
00000010  00 7b 00 00 00 00 00 04  00 35 2e 37 2e 31 36 2d  |.{.......5.7.16-|
00000020  64 65 62 75 67 2d 6c 6f  67 00 00 00 00 00 00 00  |debug-log.......|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000040  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 13  |................|
00000050  38 0d 00 08 00 12 00 04  04 04 04 12 00 00 5f 00  |8............._.|
00000060  04 1a 08 00                                       |....|
00000064

fe 62 69 6e     binlog的Magic Number,通过宏BINLOG_MAGIC定义,在open_binlog()中写入

                事件的头部信息
57 7f ad 58     从1970.1.1以来的秒数,小端存储为0x58ad7f57
0f              日志类型
ea 0c 00 00     server-id,也就是0x0cea(3306)
77 00 00 00     整个事件的大小,0x77(119)
7b 00 00 00     下个事件的偏移量,0x7b(123)
00 00           Flag

                文件开始是以一个FORMAT_DESCRIPTION_EVENT事件开始
04 00           binlog版本信息,v4
35 2e 37 2e ... 50字节,服务器版本信息,通过MYSQL_SERVER_VERSION宏定义,可通过SELECT version()查看
... ...

----- 可以根据mysqlbinlog查看偏移量
$ hexdump mysql-bin.000024 -C -s 520 -n 200

Tips: 有时候我们想查看某个 event 具体的二进制内容,此时可以通过 mysqlbinlog 查看具体 SQL 的偏移量,也就是 at NNN 中的数字。

Binlog 源码解析

如上 binlog 是由许多 event 组成,具体的类型是通过 enum Log_event_type 进行定义的,当然,可以直接查看当前包含的类型。

enum Log_event_type
{
  UNKNOWN_EVENT= 0,
  START_EVENT_V3= 1,
  QUERY_EVENT= 2,
  STOP_EVENT= 3,
  ROTATE_EVENT= 4,
  INTVAR_EVENT= 5,
  LOAD_EVENT= 6,
  SLAVE_EVENT= 7,
  CREATE_FILE_EVENT= 8,
  APPEND_BLOCK_EVENT= 9,
  EXEC_LOAD_EVENT= 10,
  DELETE_FILE_EVENT= 11,
  ... ...
};

需要注意的是,上面的部分 event 已经被弃用,但是为了兼容性,实际还保存着;这里只介绍几个比较常见的事件类型:

  • GTID_LOG_EVENT 在 GTID 模式下,每个事务的 GTID 序号被记录到这种 EVENT 中;
  • TABLE_MAP_EVENT 用于记录库名、表名以及字段类型,利用这些元数据,可用于后续事件的数据解析;

在 ROW 模式下,每次执行 INSERTUPDATEDELETE 之前,都有 TABLE_MAP_EVENT 事件,用于映射元数据信息;

初始化

与 binlog 相关的代码主要在 sql/binlog.cc 文件中,其中会初始化一个实例,代码如下。

MYSQL_BIN_LOG mysql_bin_log(&sync_binlog_period, WRITE_CACHE);

第一个参数 sync_binlog_period 也就是 sync_binlog 的设置值。

参考

关于日志内容,详细介绍可以参考官方文档 MySQL Server Logs,而 binlog 相关还可以参考官方文档 MySQL Internals Manual - The Binary Log,以及 Binary Logging Options and Variables

对于 binlog 日志格式,事件格式介绍,事件分类等,可以参考 MySQL Internals Manual - Replication Protocol