平平淡淡从从容容

0%

MySQL各种日志

发表于 分类于 4.3k 4 分钟

一日之计在于晨，一年之计在于春，一生之计在于勤。

一、各种日志

  1. 查询日志：query log，记录客户端操作的所有sql语句，包括select查询语句在内。

    • 由于查询日志纪录了所有数据库的操作，因此对于访问频繁的应用，该日志会对系统性能造成一定影响，通常建议关闭此日志
    • 即便是执行不成功的操作也会被记录在该文件中

  2. 慢查询日志：slow query log，记录了执行时间超过long_query_time参数值的sql语句。

    • MySQL的慢查询日志是MySQL提供的一种日志记录，它用来记录在MySQL中响应时间超过阀值的语句，具体指运行时间超过long_query_time值的SQL，则会被记录到慢查询日志中。
    • 慢查询日志可以有效的帮助我们发现实际应用中sql的性能问题，找出执行效率低下的sql语句

  3. 错误日志：error log，它包含一下几种：

    • mysqld启动和关闭过程中输出的事件信息
    • mysqld运行中产生的错误信息
    • event scheduler(事件调度器)运行一个event时产生的日志信息
    • 在主从复制架构中的从服务器上启动从服务器线程时产生的信息

  1. 二进制日志：binary log-MySQL的bin log三种工作模式：Row level/Statement level/Mixed。

    • MySQ的bin log是二进制日志归档文件，用于记录MySQL的数据更新操作(增删改)，另外在主从复制中也是通过binlog来实现。

    • 二进制日志需要借助mysqlbinlog这个工具进行查看，该日志里面记录的所有的DDL和DML语句，但select语句除外。

    • binlog的写入逻辑比较简单：事务执行过程中，先把日志写到 binlog cache，事务提交的时候，再把 binlog cache 写到 binlog 文件中。

      • 一个事务的 binlog 是不能被拆开的，因此不论这个事务多大，也要确保一次性写入。这就涉及到了 binlog cache 的保存问题。
      • 系统给 binlog cache 分配了一片内存，每个线程一个，参数 binlog_cache_size 用于控制单个线程内 binlog cache 所占内存的大小。如果超过了这个参数规定的大小，就要暂存到磁盘。

    • 事务提交的时候，执行器把 binlog cache 里的完整事务写入到 binlog 中，并清空 binlog cache。

    • 每个线程有自己 binlog cache，但是共用同一份 binlog 文件。

    • write 和 fsync 的时机，是由参数 sync_binlog 控制的：

      • sync_binlog=0 的时候，表示每次提交事务都只 write，不 fsync；
      • sync_binlog=1 的时候，表示每次提交事务都会执行 fsync；
      • sync_binlog=N(N>1) 的时候，表示每次提交事务都 write，但累积 N 个事务后才 fsync。

    • 三种工作模式

      • Row level：日志中会记录每一行数据被修改的情况，然后在slave端对相同的数据进行修改。
        • 优点：能清楚的记录每一行数据修改的细节
        • 缺点：数据量太大
      • Statement level(默认)：每一条被修改数据的sql都会记录到master的bin-log中，slave在复制的时候sql进程会解析成和原来master端执行过的相同的sql再次执行
        • 优点：解决了 Row level下的缺点，不需要记录每一行的数据变化，减少bin-log日志量，节约磁盘IO，提高新能
        • 缺点：容易出现主从复制不一致
      • Mixed(混合模式)：结合了Row level和Statement level的优点

    • 相关问题：一个事务的 binlog 是有完整格式的，分别如下：

      • statement格式的binlog，最后会有COMMIT
      • row格式的binlog，最后会有一个XID event

redo log和binlog是怎么关联起来的?
它们有一个共同的数据字段，叫 XID。崩溃恢复的时候，会按顺序扫描 redo log：

  • 如果碰到既有prepare又有commit的redo log，就直接提交
  • 如果碰到只有prepare而没有commit的redo log，就拿着XID去binlog找对应的事务

MySQL在记录 binlog 的时候，不论是 create table 还是 alter table 语句，都是原样记录，甚至于连空格都不变。

扩展

DML(data manipulation language)数据操纵语言：就是我们最经常用到的 SELECT、UPDATE、INSERT、DELETE，主要用来对数据库的数据进行一些操作。

DDL(data definition language)数据库定义语言：就是我们在创建表的时候用到的一些sql，比如说：CREATE、ALTER、DROP等。DDL主要是用在定义或改变表的结构，数据类型，表之间的链接和约束等初始化工作上。

DCL(Data Control Language)数据库控制语言：是用来设置或更改数据库用户或角色权限的语句，包括（grant,deny,revoke等）语句

  1. redo log

    • 为了控制redo log的写入策略，InnoDB 提供了innodb_flush_log_at_trx_commit参数，它有三种可能取值：
      • 设置为 0 的时候，表示每次事务提交时都只是把redo log留在redo logbuffer中
      • 设置为 1 的时候，表示每次事务提交时都将redo log直接持久化到磁盘
      • 设置为 2 的时候，表示每次事务提交时都只是把redo log写到page cache
    • InnoDB有一个后台线程，每隔1秒就会把redo log buffer中的日志调用write写到文件系统的page cache，然后调用fsync持久化到磁盘。
    • 双1即binary log中sync_binlog参数和redo log中innodb_flush_log_at_trx_commit同时设置为1

  2. undo log

  3. 中继日志：reley log，主从复制架构中，从服务器用于保存从主服务器的二进制日志中读取到的事件

二、使用

  1. 查看日志开启状态show variables like 'log_%';

  2. 开启binlog

    • vim my.cnf(通过brew默认安装)
    1
    2
    3
    log_bin=ON
    log_bin_basename=/usr/local/var/mysql/mysql-bin
    log_bin_index=/usr/local/var/mysql/mysql-bin.index
    • 报错：ERROR] You have enabled the binary log, but you haven't provided the mandatory server-id. Please refer to the proper server start-up parameters documentation
    • vim my.cnf，加入并重启
1
server-id=1
  • 报错unknown variable 'log_bin_basename=/usr/local/var/mysql/mysql-bin'，教程比较老了，直接看官网，然后重启
1
2
3
server-id=1
log-bin=mysql-bin
binlog_format=Statement

binlog_format有三种格式

Row格式：日志中会记录成每一行数据被修改的形式，然后在 slave 端再对相同的数据进行修改。

优点：在row模式下，bin-log中可以不记录执行的SQL语句的上下文相关的信息，仅仅只需要记录那一条记录被修改了，修改成什么样了。所以row的日志内容会非常清楚的记录下每一行数据修改的细节，非常容易理解。它不会出现某些特定情况下的存储过程、function、trigger的调用和触发无法被正确复制的问题。

缺点：在row模式下，所有的执行的语句当记录到日志中的时候，都将以每行记录的修改来记录，这样可能会产生大量的日志内容，比如有这样一条update语句：UPDATE product SET owner_member_id = 'b' WHERE owner_member_id = 'a';，执行之后日志中记录的不是这条update语句所对应的事件(MySQL以事件的形式来记录bin-log日志)，而是这条语句所更新的每一条记录的变化情况，这样就记录成很多条记录被更新的很多个事件，因此bin-log日志的量就会很大。尤其是当执行alter table之类的语句的时候产生的日志量是惊人的。

Statement格式：每一条会修改数据的SQL都会记录到master的bin-log中，slave 在复制的时候SQL进程会解析成和原来master端执行过的相同的SQL再次执行。

优点：在statement模式下，首先就是解决了row模式的缺点，不需要记录每一行数据的变化，减少了bin-log日志量，节省I/O以及存储资源，提高性能。因为他只需要记录在master上所执行的语句的细节，以及执行语句时候的上下文的信息。

缺点：在statement模式下，由于他是记录的执行语句，所以为了让这些语句在slave端也能正确执行，必须记录每条语句在执行的时候的一些相关信息，也就是上下文信息，以保证所有语句在slave端杯执行的时候能够得到和在master端执行时候相同的结果。在statement中目前已经发现的就有不少情况会造成MySQL的复制出现问题，主要是修改数据的时候使用了某些特定的函数或者功能的时候会出现，比如sleep()函数在有些版本中就不能被正确复制，在存储过程中使用了last_insert_id()函数可能会使slave和master上得到不一致的id等等。由于row是基于每一行来记录的变化，所以不会出现类似的问题。

Mixed格式：从5.1.8版本开始MySQL提供了前两种模式的结合。在Mixed模式下MySQL会根据执行的每一条具体的SQL语句来区分对待记录的日志形式，也就是在statement和row之间选择一种。

新版本中的statment还是和以前一样仅仅记录执行的语句，新版本的MySQL中对row模式也被做了优化，并不是所有的修改都会以row模式来记录，比如遇到表结构变更的时候就会以statement模式来记录，如果SQL语句确实就是update或者delete等修改数据的语句，那么还是会记录所有行的变更。

  1. 查看所有binlog日志列表show master logs;

  2. 清空所有binlogreset master;

  3. 查看binlog内容/usr/local/Cellar/mysql@5.7/5.7.32/bin/mysqlbinlog /usr/local/var/mysql/mysql-bin.000001

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210401 16:51:24 server id 1  end_log_pos 123 CRC32 0xf4312400 	Start: binlog v 4, server v 5.7.32-log created 210401 16:51:24 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
jIllYA8BAAAAdwAAAHsAAAABAAQANS43LjMyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAACMiWVgEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AQAkMfQ=
'/*!*/;
# at 123
#210401 16:51:24 server id 1  end_log_pos 154 CRC32 0x20465e25 	Previous-GTIDs
# [empty]
# at 154
#210401 16:53:45 server id 1  end_log_pos 219 CRC32 0x537a6eed 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#210401 16:53:45 server id 1  end_log_pos 306 CRC32 0xd115c030 	Query	thread_id=2	exec_time=0	error_code=0
SET TIMESTAMP=1617267225/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
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=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 306
# at 338
#210401 16:53:45 server id 1  end_log_pos 338 CRC32 0x190bcdc7 	Intvar
SET INSERT_ID=2/*!*/;
#210401 16:53:45 server id 1  end_log_pos 471 CRC32 0x2c732496 	Query	thread_id=2	exec_time=0	error_code=0
use `playcrab`/*!*/;
SET TIMESTAMP=1617267225/*!*/;
insert into user(name,created) values('李四',111)
/*!*/;
# at 471
#210401 16:53:45 server id 1  end_log_pos 502 CRC32 0x4546743b 	Xid = 17
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*/;
  1. MySQL以事件event的形式来记录binlog，日志查看binlog eventshow binlog events in 'mysql-bin.000001'\G;
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
*************************** 1. row ***************************
   Log_name: mysql-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 123
       Info: Server ver: 5.7.32-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: mysql-bin.000001
        Pos: 123
 Event_type: Previous_gtids
  Server_id: 1
End_log_pos: 154
       Info:
*************************** 3. row ***************************
   Log_name: mysql-bin.000001
        Pos: 154
 Event_type: Anonymous_Gtid
  Server_id: 1
End_log_pos: 219
       Info: SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
*************************** 4. row ***************************
   Log_name: mysql-bin.000001
        Pos: 219
 Event_type: Query
  Server_id: 1
End_log_pos: 306
       Info: BEGIN
*************************** 5. row ***************************
   Log_name: mysql-bin.000001
        Pos: 306
 Event_type: Intvar
  Server_id: 1
End_log_pos: 338
       Info: INSERT_ID=2
*************************** 6. row ***************************
   Log_name: mysql-bin.000001
        Pos: 338
 Event_type: Query
  Server_id: 1
End_log_pos: 471
       Info: use `playcrab`; insert into user(name,created) values('李四',111)
*************************** 7. row ***************************
   Log_name: mysql-bin.000001
        Pos: 471
 Event_type: Xid
  Server_id: 1
End_log_pos: 502
       Info: COMMIT /* xid=17 */
7 rows in set (0.00 sec)

ERROR:
No query specified

mysql> show binlog events in 'mysql-bin.000001'\G;
*************************** 1. row ***************************
   Log_name: mysql-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 123
       Info: Server ver: 5.7.32-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: mysql-bin.000001
        Pos: 123
 Event_type: Previous_gtids
  Server_id: 1
End_log_pos: 154
       Info:
*************************** 3. row ***************************
   Log_name: mysql-bin.000001
        Pos: 154
 Event_type: Anonymous_Gtid
  Server_id: 1
End_log_pos: 219
       Info: SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
*************************** 4. row ***************************
   Log_name: mysql-bin.000001
        Pos: 219
 Event_type: Query
  Server_id: 1
End_log_pos: 306
       Info: BEGIN
*************************** 5. row ***************************
   Log_name: mysql-bin.000001
        Pos: 306
 Event_type: Intvar
  Server_id: 1
End_log_pos: 338
       Info: INSERT_ID=2
*************************** 6. row ***************************
   Log_name: mysql-bin.000001
        Pos: 338
 Event_type: Query
  Server_id: 1
End_log_pos: 471
       Info: use `playcrab`; insert into user(name,created) values('李四',111)
*************************** 7. row ***************************
   Log_name: mysql-bin.000001
        Pos: 471
 Event_type: Xid
  Server_id: 1
End_log_pos: 502
       Info: COMMIT /* xid=17 */
  1. 控制binlog落盘参数
    • sync_binlog
    • innodb_flush_log_at_trx_commit

三、参考

  1. 参考一
  2. 参考二
  3. 参考三