不管是哪个数据库产品,一定会有日志文件。在MySQL中,主要有5种日志文件:
- 错误日志(error log):记录mysql服务的启停时正确和错误的信息,还记录启动、停止、运行过程中的错误信息。
- 查询日志(general log):记录建立的客户端连接和执行的语句。
- 二进制日志(bin log):记录所有更改数据的语句,可用于数据复制。
- 慢查询日志(slow log):记录所有执行时间超过long_query_time的所有查询或不使用索引的查询。
- 中继日志(relay log):主从复制时使用的日志。
15.1、日志的刷新操作
以下操作会刷新日志文件,刷新日志文件时会关闭旧的日志文件并重新打开日志文件。对于有些日志类型,如二进制日志,刷新日志会滚动日志文件,而不仅仅是关闭并重新打开。
mysql> FLUSH LOGS;
shell> mysqladmin flush-logs -uroot -p
shell> mysqladmin refresh -uroot -p
15.2、错误日志
记录了MySQL服务启动和停止正确和错误的信息,还记录了mysqld实例运行过程中发生的错误事件信息。
可以在MySQL配置文件中的mysqld配置部分使用” --log-error=[file_name]
“来指定mysqld记录的错误日志文件,如果没有指定file_name,则默认的错误日志文件为datadir目录下的 hostname
.err ,hostname表示当前的主机名。如果不知道错误日志的位置,可以查看变量log_error来查看。
# 查看错误日志的位置
SHOW VARIABLES LIKE '%log_error%'
SELECT @@log_error
在MySQL 5.5.7之前,刷新日志操作(如flush logs)会备份旧的错误日志(以_old结尾),并创建一个新的错误日志文件并打开,在MySQL 5.5.7之后,执行刷新日志的操作时,错误日志会关闭并重新打开,如果错误日志不存在,则会先创建。
在MariaDB/MySQL正在运行状态下删除错误日志后,不会自动创建错误日志,只有在刷新日志的时候才会创建一个新的错误日志文件。
15.3、一般查询日志
查询日志分为一般查询日志和慢查询日志,它们是通过查询是否超出变量 long_query_time
指定时间的值来判定的。在超时时间内完成的查询是一般查询,可以将其记录到一般查询日志中,但是建议关闭这种日志(默认是关闭的),超出时间的查询是慢查询,可以将其记录到慢查询日志中。
--general_log={0|1}
“来决定是否启用一般查询日志,使用” --general_log_file=file_name
“来指定查询日志的路径。不给定路径时默认的文件名以 hostname
.log 命名。
和查询日志有关的变量有:
# 指定慢查询超时时长,超出此时长的属于慢查询,会记录到慢查询日志中
long_query_time = 10
# 定义一般查询日志和慢查询日志的输出格式,不指定时默认为file
log_output={TABLE|FILE|NONE}
- TABLE:表示记录日志到表中.
- FILE:表示记录日志到文件中.
- NONE:表示不记录日志。
只要这里指定为NONE,即使开启了一般查询日志和慢查询日志,也都不会有任何记录。
和一般查询日志相关的变量有:
# 是否启用一般查询日志,为全局变量,必须在global上修改。
general_log=off
# 在session级别控制是否启用一般查询日志,默认为off,即启用
sql_log_off=off
# 默认是库文件路径下主机名加上.log
general_log_file=/data/mysqldata/hostname.log
默认没有开启一般查询日志,也不建议开启一般查询日志。此处打开该类型的日志,看看是如何记录一般查询日志的。
首先开启一般查询日志
# 启用一般查询日志
mysql> set @@global.general_log=1;
# 可以看出我的主机名称s1 一般查询日志文件时s1.log
[root@s1 ~]# ll /data/mysqldata/*.log
-rw-r-----. 1 mysql mysql 184 Dec 15 14:39 /data/mysqldata/s1.log
执行几个语句。
mysql> select host,user from mysql.user;
mysql> show variables like "%error%";
mysql> use mysql_test;
mysql> create table tt(id int);
mysql> insert into tt values(233);
mysql> set @a:=3;
查看一般查询日志的内容。
[root@s1 ~]# cat /data/mysqldata/s1.log
2020-12-15T06:44:30.821127Z 6 Query show databases
2020-12-15T06:44:38.736325Z 6 Query SELECT DATABASE()
2020-12-15T06:44:38.736494Z 6 Init DB mysql_test
2020-12-15T06:44:44.932452Z 6 Query create table tt(id int)
2020-12-15T06:44:50.195845Z 6 Query insert into ttt values(233)
2020-12-15T06:45:00.035198Z 6 Query insert into tt values(233)
2020-12-15T06:45:09.826891Z 6 Query set @a:=3
由此可知,一般查询日志记录的不止是select语句,几乎所有的语句都会记录。
15.4、慢查询日志
查询超出变量 long_query_time
指定时间值的为慢查询。但是查询获取锁(包括锁等待)的时间不计入查询时间内。
mysql记录慢查询日志是在查询执行完毕且已经完全释放锁之后才记录的,因此慢查询日志记录的顺序和执行的SQL查询语句顺序可能会不一致(例如语句1先执行,查询速度慢,语句2后执行,但查询速度快,则语句2先记录)。
注意,MySQL 5.1之后就支持微秒级的慢查询超时时长,对于DBA来说,一个查询运行0.5秒和运行0.05秒是非常不同的,前者可能索引使用错误或者走了表扫描,后者可能索引使用正确。
另外,指定的慢查询超时时长表示的是超出这个时间的才算是慢查询,等于这个时间的不会记录。
和慢查询有关的变量:
# 指定慢查询超时时长(默认10秒),超出此时长的属于慢查询
long_query_time=10
# 定义一般查询日志和慢查询日志的输出格式,默认为file
log_output={TABLE|FILE|NONE}
# 是否启用慢查询日志,默认不启用
log_slow_queries={yes|no}
# 也是是否启用慢查询日志,此变量和log_slow_queries修改一个另一个同时变化
slow_query_log={1|ON|0|OFF}
# 默认路径为库文件目录下主机名加上-slow.log
slow_query_log_file=/data/mysqldata/hostname-slow.log
# 查询没有使用索引的时候是否也记入慢查询日志
log_queries_not_using_indexes=OFF
现在启用慢查询日志。
mysql> set @@global.slow_query_log=on;
因为默认超时时长为10秒,所以进行一个10秒的查询。
mysql> select sleep(10);
查看慢查询日志文件。这里看到虽然sleep了10秒,但是最后查询时间超出了847微秒,因此这里也记录了该查询。
[root@s1 ~]# cat /data/mysqldata/s1-slow.log
/usr/local/jdy/mysql/bin/mysqld, Version: 5.7.22 (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
/usr/local/jdy/mysql/bin/mysqld, Version: 5.7.22 (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2020-12-15T07:08:39.066210Z
# User@Host: root[root] @ [192.168.116.1] Id: 7
# Query_time: 10.001191 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1608016119;
select sleep(10);
随着时间的推移,慢查询日志文件中的记录可能会变得非常多,这对于分析查询来说是非常困难的。好在提供了一个专门归类慢查询日志的工具mysqldumpslow。
mysqldumpslow [options] filename
options
- -d: debug
- -v:显示详细信息
- -t NUM:仅显示前n条查询
- -a:归类时不要使用N替换数字,S替换字符串
- -g PATTERN:通过grep来筛选select语句。
该工具归类的时候,默认会将同文本但变量值不同的查询语句视为同一类,并使用N代替其中的数值变量,使用S代替其中的字符串变量。可以使用-a来禁用这种替换。如:
[root@s1 ~]# ln -s /usr/local/jdy/mysql/bin/mysqldumpslow /usr/bin
[root@s1 ~]# mysqldumpslow /data/mysqldata/s1-slow.log
Reading mysql slow query log from /data/mysqldata/s1-slow.log
Count: 1 Time=10.00s (10s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@[192.168.116.1]
select sleep(N)
[root@s1 ~]# mysqldumpslow -a /data/mysqldata/s1-slow.log
Reading mysql slow query log from /data/mysqldata/s1-slow.log
Count: 1 Time=10.00s (10s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@[192.168.116.1]
select sleep(10)
-d选项启用调试功能。
[root@s1 ~]# mysqldumpslow -d /data/mysqldata/s1-slow.log
Reading mysql slow query log from /data/mysqldata/s1-slow.log
[[/usr/local/jdy/mysql/bin/mysqld, Version: 5.7.22 (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
/usr/local/jdy/mysql/bin/mysqld, Version: 5.7.22 (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2020-12-15T07:08:39.066210Z
# User@Host: root[root] @ [192.168.116.1] Id: 7
# Query_time: 10.001191 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1608016119;
select sleep(10);
]]
<<>>
<<>>
<<# Time: 2020-12-15T07:08:39.066210Z
# User@Host: root[root] @ [192.168.116.1] Id: 7
# Query_time: 10.001191 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1608016119;
select sleep(10);
>> at /usr/bin/mysqldumpslow line 97, <> chunk 1.
[[# Time: 2020-12-15T07:08:39.066210Z
# User@Host: root[root] @ [192.168.116.1] Id: 7
# Query_time: 10.001191 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1608016119;
select sleep(10);
]]
{{ select sleep(N)}}
Count: 1 Time=10.00s (10s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@[192.168.116.1]
select sleep(N)
慢查询在SQL语句调优的时候非常有用,应该将它启用起来,且应该让慢查询阈值尽量小,例如1秒甚至低于1秒。就像一天执行上千次的1秒语句,和一天执行几次的20秒语句,显然更值得去优化这个1秒的语句。
15.5、二进制日志
(1)、二进制日志文件
引起或可能引起数据库改变(如delete语句但没有匹配行)的事件信息,但绝不会包括select和show这样的查询语句。语句以“事件”的形式保存,所以包含了时间、事件开始和结束位置等信息。
以事件形式记录的,不是事务日志(但可能是基于事务来记录二进制日志),不代表它只记录innodb日志,myisam表也一样有二进制日志。
对于事务表的操作,二进制日志只在事务提交的时候一次性写入(基于事务的innodb二进制日志),提交前的每个二进制日志记录都先cache,提交时写入。
所以,对于事务表来说,一个事务中可能包含多条二进制日志事件,它们会在提交时一次性写入。而对于非事务表的操作,每次执行完语句就直接写入。
MySQL默认没有启动二进制日志,要启用二进制日志使用 --log-bin=[on|off|file_name]
选项指定,如果没有给定file_name,则默认为datadir下的主机名加“-bin”,并在后面跟上一串数字表示日志序列号,如果给定的日志文件中包含了后缀(logname.suffix)将忽略后缀部分。
[root@s1 ~]# ll /data/mysqldata/
-rw-r-----. 1 mysql mysql 154 Dec 15 16:06 on.000001
-rw-r-----. 1 mysql mysql 12 Dec 15 16:06 on.index
对于mysql 5.7,直接启动binlog可能会导致mysql服务启动失败,这时需要在配置文件中的mysqld为mysql实例分配server_id。
[mysqld]
# server_id=1234
log-bin=[on|filename]
创建一个二进制日志索引文件,当二进制日志文件滚动的时候会向该文件中写入对应的信息。所以该文件包含所有使用的二进制日志文件的文件名。默认情况下该文件与二进制日志文件的文件名相同,扩展名为’.index’。要指定该文件的文件名使用 --log-bin-index[=file_name]
选项。当mysqld在运行时不应手动编辑该文件,免得mysqld变得混乱。
当重启mysql服务或刷新日志或者达到日志最大值时,将滚动二进制日志文件,滚动日志时只修改日志文件名的数字序列部分。
二进制日志文件的最大值通过变量 max_binlog_size
设置(默认值为1G)。但由于二进制日志可能是基于事务来记录的(如innodb表类型),而事务是绝对不可能也不应该跨文件记录的,如果正好二进制日志文件达到了最大值但事务还没有提交则不会滚动日志,而是继续增大日志,所以 max_binlog_size
指定的值和实际的二进制日志大小不一定相等。
因为二进制日志文件增长迅速,但官方说明因此而损耗的性能小于1%,且二进制目的是为了恢复定点数据库和主从复制,所以出于安全和功能考虑,极不建议将二进制日志和datadir放在同一磁盘上。
(2)、查看二进制日志
MySQL中查看二进制日志的方法主要有几种。
- 使用mysqlbinlog工具。
- 使用show显示对应的信息。
# 查看使用了哪些日志文件
SHOW {BINARY | MASTER} LOGS
# 查看日志中进行了哪些操作
SHOW BINLOG EVENTS [IN 'log_name'] [FROM pos]
# 显式主服务器中的二进制日志信息
SHOW MASTER STATUS
①、mysqlbinlog
二进制日志可以使用mysqlbinlog命令查看。
mysqlbinlog [option] log-file1 log-file2...
以下是常用的几个选项:
- -d(--database=name):只查看指定数据库的日志操作
- -o(--offset=#):忽略掉日志中的前n个操作命令
- -r(--result-file=name):将输出的日志信息输出到指定的文件中,使用重定向也一样可以。
- -s(--short-form):显示简单格式的日志,只记录一些普通的语句,会省略掉一些额外的信息如位置信息和时间信息以及基于行的日志。可以用来调试,生产环境千万不可使用
- --set-charset=char_name:在输出日志信息到文件中时,在文件第一行加上set names char_name
- --start-datetime(--stop-datetime):指定输出开始时间和结束时间内的所有日志信息
- --start-position=#(--stop-position=#):指定输出开始位置和结束位置内的所有日志信息
- -v(-vv):显示更详细信息,基于row的日志默认不会显示出来,此时使用-v或-vv可以查看
在进行测试之前,先对日志进行一次刷新,以方便解释二进制日志的信息。
shell> mysqladmin -uroot -p refresh
假设现在的日志文件是mysql-bin.000001,里面暂时只有一些初始信息,没有记录任何操作过的记录。
下面是每个二进制日志文件的初始信息。可以看到记录了时间和位置信息(at 4)。
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001
现在在数据库中执行下面的操作:
use test;
create table student(studentid int not null primary key,name varchar(30) not null,gender enum('female','mail'));
alter table student change gender gender enum('female','male');
insert into student values(1,'malongshuai','male'),(2,'gaoxiaofang','female');
再查看二进制日志信息。
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001
将上述信息整理为下图:其中timestamp记录的是从1970-01-01到现在的总秒数时间戳,可以使用 date -d ‘@1490736093’ 转换。
- 位置0-120记录的是二进制日志的一些固定信息。
- 位置120-305记录的是use和create table语句,语句的记录时间为5:20:00。但注意,这里的use不是执行的use语句,而是MySQL发现要操作的数据库为test,而自动进行的操作并记录下来。人为的use语句是不会记录的。
- 位置305-441记录的是alter table语句,语句的记录时间为5:20:21。
- 位置441-702记录的是insert操作,因为该操作是DML语句,因此记录了事务的开始BEGIN和提交COMMIT。
- begin的起止位置为441-520;
- insert into语句的起止位置为520-671,记录的时间和自动开启事务的begin时间是一样的;
- commit的起止位置为671-702。
使用-r命令将日志文件导入到指定文件中,使用重定向也可以实现同样的结果。并使用-s查看简化的日志文件。
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001 -r /tmp/binlog.000001
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001 -s > /tmp/binlog.sample
比较这两个文件,看看简化的日志文件简化了哪些东西。
从上图中可以看出,使用-s后,少了基于行的日志信息,也少了记录的位置和时间信息。
使用-o可以忽略前N个条目,例如上面的操作涉及了6个操作。忽略掉前3个后的日志显示如下:可以看到直接从位置441开始显示了。
[root@s1 ~]# mysqlbinlog --no-defaults -o 3 /data/mysqldata/on.000001
使用-d可以只显示指定数据库相关的操作。例如先切换到其他数据库进行一番操作,然后再使用-d查看日志。
mysql> use mysql_test;
mysql> create table mytest(id int);
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001 -d bigdata
可以看到,除了指定的mysql数据库的信息输出了,还非常简化的输出了其他数据库的信息。
mysqlbinlog最有用的两个选项就是指定时间和位置来输出日志。
指定时间时,将输出指定时间范围内的日志。指定的时间可以不和日志中记录的日志相同。
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001 --start-datetime='2017-03-28 00:00:01' --stop-datetime='2017-03-29 05:21:23'
同理指定位置也一样,但是指定位置时有个要求是如果指定起始位置,则必须指定日志文件中明确的起始位置。例如,日志文件中有位置120、305、441,可以指定起始和结束位置为120、500,但是不可以指定起止位置为150、500,因为日志文件中不存在150这个位置。
[root@s1 ~]# mysqlbinlog --no-defaults /data/mysqldata/on.000001 --start-position=150 --stop-position=441
②、show binary logs
该语句用于查看当前使用了哪些二进制日志文件。
可以通过查看二进制的index文件来查看当前正在使用哪些二进制日志。
[root@s1 ~]# cat /data/mysqldata/on.index
./on.000001
./on.000002
./on.000003
也可以在mysql环境中使用 show {binary | master} logs 来查看。binary和master是同义词。
mysql> show binary logs;
+-----------+-----------+
| Log_name | File_size |
+-----------+-----------+
| on.000001 | 11977 |
| on.000002 | 177 |
| on.000003 | 154 |
+-----------+-----------+
③、show binlog events
该语句用于查看日志中进行了哪些操作。
mysql> show binlog events in 'on.000002';
可以指定起始位置。同样,起始位置必须指定正确,不能指定不存在的位置。
mysql> SHOW BINLOG EVENTS IN 'on.000001' FROM 1255;
④、show master status
该语句用于显示主服务器中的二进制日志信息。如果是主从结构,它只会显示主从结构中主服务器的二进制日志信息。
mysql> show master status;
+-----------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+-----------+----------+--------------+------------------+-------------------+
| on.000003 | 154 | | | |
+-----------+----------+--------------+------------------+-------------------+
可以查看到当前正在使用的日志及下一事件记录的开始位置,还能查看到哪些数据库需要记录二进制日志,哪些数据库不记录二进制日志。
(3)、删除二进制日志
删除二进制日志有几种方法。不管哪种方法,都会将删除后的信息同步到二进制index文件中。
1.reset master将会删除所有日志,并让日志文件重新从000001开始。
mysql> reset master;
2.PURGE { BINARY | MASTER } LOGS { TO ‘log_name’ | BEFORE datetime_expr }
# 将会清空00000X之前的所有日志文件。例如删除000006之前的日志文件
purge master logs to "binlog_name.00000X"
mysql> purge master logs to "on.000001";
mysql> purge binary logs to "on.000001";
master和binary是同义词
# 将会删除指定日期之前的所有日志。但是若指定的时间处在正在使用中的日志文件中,将无法进行purge。
purge master logs before 'yyyy-mm-dd hh:mi:ss'
mysql> purge master logs before '2017-03-29 07:36:40';
mysql> show warnings;
+---------+------+---------------------------------------------------------------------------+
| Level | Code | Message |
+---------+------+---------------------------------------------------------------------------+
| Warning | 1868 | file ./mysql-bin.000003 was not purged because it is the active log file.
3.使用--expire_logs_days=N选项指定过了多少天日志自动过期清空。
(4)、二进制日志的记录格式
在MySQL 5.1之前,MySQL只有一种基于语句statement形式的日志记录格式。即将所有的相关操作记录为SQL语句形式。但是这样的记录方式对某些特殊信息无法同步记录,例如uuid,now()等这样动态变化的值。
从MySQL 5.1开始,MySQL支持statement、row、mixed三种形式的记录方式。row形式是基于行来记录,也就是将相关行的每一列的值都在日志中保存下来,这样的结果会导致日志文件变得非常大,但是保证了动态值的确定性。还有一种mixed形式,表示如何记录日志由MySQL自己来决定。
日志的记录格式由变量 binlog_format 来指定。其值有:row,statement,mixed。innodb引擎的创始人之一在博客上推荐使用row格式。
下面将记录格式改为row。
mysql> alter table student add birthday datetime default now();
mysql> flush logs;
mysql> set binlog_format='row';
mysql> insert into student values(7,'xiaowoniu','female',now());
(5)、二进制日志相关的变量
注意:在配置binlog相关变量的时候,相关变量名总是搞混,因为有的是binlog,有的是log_bin,当他们分开的时候,log在前,当它们一起的时候,bin在前。在配置文件中也同样如此。
变量名称 | 变量说明 |
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
在innodb的主从复制结构中,如果启用了二进制日志(几乎都会启用),要保证事务的一致性和持久性的时候,必须将sync_binlog的值设置为1,因为每次事务提交都会写入二进制日志,设置为1就保证了每次事务提交时二进制日志都会写入到磁盘中,从而立即被从服务器复制过去。**
(6)、二进制日志定点还原数据库
只需指定二进制日志的起始位置(可指定终止位置)并将其保存到sql文件中,由mysql命令来载入恢复即可。当然直接通过管道送给mysql命令也可。
至于是基于位置来恢复还是基于时间点来恢复,这两种行为都可以。选择时间点来恢复比较直观些,并且跨日志文件恢复时更方便。
mysqlbinlog --stop-datetime="2014-7-2 15:27:48" /tmp/mysql-bin.000008 | mysql -u user -p password
恢复多个二进制日志文件时:
mysqlbinlog mysql-bin.[*] | mysql -uroot -p password
或者将它们导入到一个文件中后恢复。
mysqlbinlog mysql-bin.000001 > /tmp/a.sql
mysqlbinlog mysql-bin.000002 >>/tmp/a.sql
mysql -u root -p password -e "source /tmp/a.sql"
@s1 ~