MySQL数据库日志的详细分析

前言

官方手册:https://dev.mysql.com/doc/refman/5.7/en/server-logs.html

不管是哪个数据库产品，一定会有日志文件。在MariaDB/MySQL中，主要有5种日志文件：

1.错误日志(error log)：记录mysql服务的启停时正确和错误的信息，还记录启动、停止、运行过程中的错误信息。

2.查询日志(general log)：记录建立的客户端连接和执行的语句。

3.二进制日志(bin log)：记录所有更改数据的语句，可用于数据复制。

4.慢查询日志(slow log)：记录所有执行时间超过long_query_time的所有查询或不使用索引的查询。

5.中继日志(relay log)：主从复制时使用的日志。

除了这5种日志，在需要的时候还会创建DDL日志。本文暂先讨论错误日志、一般查询日志、慢查询日志和二进制日志，中继日志和主从复制有关，将在复制的章节中介绍。下一篇文章将介绍innodb事务日志，见：MySQL的事务日志。

1.日志刷新操作

以下操作会刷新日志文件，刷新日志文件时会关闭旧的日志文件并重新打开日志文件。对于有些日志类型，如二进制日志，刷新日志会滚动日志文件，而不仅仅是关闭并重新打开。

2.错误日志

错误日志是最重要的日志之一，它记录了MariaDB/MySQL服务启动和停止正确和错误的信息，还记录了mysqld实例运行过程中发生的错误事件信息。

可以使用"–log-error=[file_name]"来指定mysqld记录的错误日志文件，如果没有指定file_name，则默认的错误日志文件为datadir目录下的`hostname`.err，hostname表示当前的主机名。

也可以在MariaDB/MySQL配置文件中的mysqld配置部分，使用log-error指定错误日志的路径。

如果不知道错误日志的位置，可以查看变量log_error来查看。

在MySQL 5.5.7之前，刷新日志操作(如flush logs)会备份旧的错误日志(以_old结尾)，并创建一个新的错误日志文件并打开，在MySQL 5.5.7之后，执行刷新日志的操作时，错误日志会关闭并重新打开，如果错误日志不存在，则会先创建。

在MariaDB/MySQL正在运行状态下删除错误日志后，不会自动创建错误日志，只有在刷新日志的时候才会创建一个新的错误日志文件。

以下是MySQL 5.6.35启动的日志信息。

2017-03-29 01:15:14 2362 [Note] Plugin 'FEDERATED' is disabled.
2017-03-29 01:15:14 2362 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-03-29 01:15:14 2362 [Note] InnoDB: The InnoDB memory heap is disabled
2017-03-29 01:15:14 2362 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-03-29 01:15:14 2362 [Note] InnoDB: Memory barrier is not used
2017-03-29 01:15:14 2362 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-03-29 01:15:14 2362 [Note] InnoDB: Using Linux native AIO
2017-03-29 01:15:14 2362 [Note] InnoDB: Using CPU crc32 instructions
2017-03-29 01:15:14 2362 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2017-03-29 01:15:14 2362 [Note] InnoDB: Completed initialization of buffer pool
2017-03-29 01:15:14 2362 [Note] InnoDB: Highest supported file format is Barracuda.
2017-03-29 01:15:14 2362 [Note] InnoDB: 128 rollback segment(s) are active.
2017-03-29 01:15:14 2362 [Note] InnoDB: Waiting for purge to start
2017-03-29 01:15:14 2362 [Note] InnoDB: 5.6.35 started; log sequence number 3911610
2017-03-29 01:15:14 2362 [Note] Server hostname (bind-address): '*'; port: 3306
2017-03-29 01:15:14 2362 [Note] IPv6 is available.
2017-03-29 01:15:14 2362 [Note]   – '::' resolves to '::';
2017-03-29 01:15:14 2362 [Note] Server socket created on IP: '::'.
2017-03-29 01:15:14 2362 [Warning] 'proxies_priv' entry '@ root@xuexi.longshuai.com' ignored in –skip-name-resolve mode.
2017-03-29 01:15:14 2362 [Note] Event Scheduler: Loaded 0 events
2017-03-29 01:15:14 2362 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.35'  socket: '/mydata/data/mysql.sock'  port: 3306  MySQL Community Server (GPL)

3.一般查询日志

查询日志分为一般查询日志和慢查询日志，它们是通过查询是否超出变量long_query_time指定时间的值来判定的。在超时时间内完成的查询是一般查询，可以将其记录到一般查询日志中，但是建议关闭这种日志（默认是关闭的），超出时间的查询是慢查询，可以将其记录到慢查询日志中。

使用"–general_log={0|1}"来决定是否启用一般查询日志，使用"–general_log_file=file_name"来指定查询日志的路径。不给定路径时默认的文件名以`hostname`.log命名。

和查询日志有关的变量有：

TABLE表示记录日志到表中，FILE表示记录日志到文件中，NONE表示不记录日志。只要这里指定为NONE，即使开启了一般查询日志和慢查询日志，也都不会有任何记录。

和一般查询日志相关的变量有：

在MySQL 5.6以前的版本还有一个"log"变量也是决定是否开启一般查询日志的。在5.6版本开始已经废弃了该选项。

默认没有开启一般查询日志，也不建议开启一般查询日志。此处打开该类型的日志，看看是如何记录一般查询日志的。

首先开启一般查询日志。

执行几个语句。

查看一般查询日志的内容。

由此可知，一般查询日志查询的不止是select语句，几乎所有的语句都会记录。

4.慢查询日志

查询超出变量long_query_time指定时间值的为慢查询。但是查询获取锁(包括锁等待)的时间不计入查询时间内。

mysql记录慢查询日志是在查询执行完毕且已经完全释放锁之后才记录的，因此慢查询日志记录的顺序和执行的SQL查询语句顺序可能会不一致(例如语句1先执行，查询速度慢，语句2后执行，但查询速度快，则语句2先记录)。

注意，MySQL 5.1之后就支持微秒级的慢查询超时时长，对于DBA来说，一个查询运行0.5秒和运行0.05秒是非常不同的，前者可能索引使用错误或者走了表扫描，后者可能索引使用正确。

另外，指定的慢查询超时时长表示的是超出这个时间的才算是慢查询，等于这个时间的不会记录。

和慢查询有关的变量：

现在启用慢查询日志。

因为默认超时时长为10秒，所以进行一个10秒的查询。

查看慢查询日志文件。这里看到虽然sleep了10秒，但是最后查询时间超出了847微秒，因此这里也记录了该查询。

随着时间的推移，慢查询日志文件中的记录可能会变得非常多，这对于分析查询来说是非常困难的。好在提供了一个专门归类慢查询日志的工具mysqldumpslow。

该工具归类的时候，默认会将同文本但变量值不同的查询语句视为同一类，并使用N代替其中的数值变量，使用S代替其中的字符串变量。可以使用-a来禁用这种替换。如：

显然，这里归类后的结果只是精确到0.01秒的，如果想要显示及其精确的秒数，则使用-d选项启用调试功能。

慢查询在SQL语句调优的时候非常有用，应该将它启用起来，且应该让慢查询阈值尽量小，例如1秒甚至低于1秒。就像一天执行上千次的1秒语句，和一天执行几次的20秒语句，显然更值得去优化这个1秒的语句。

5.二进制日志

5.1 二进制日志文件

二进制日志包含了引起或可能引起数据库改变(如delete语句但没有匹配行)的事件信息，但绝不会包括select和show这样的查询语句。语句以"事件"的形式保存，所以包含了时间、事件开始和结束位置等信息。

二进制日志是以事件形式记录的，不是事务日志(但可能是基于事务来记录二进制日志)，不代表它只记录innodb日志，myisam表也一样有二进制日志。

对于事务表的操作，二进制日志只在事务提交的时候一次性写入(基于事务的innodb二进制日志)，提交前的每个二进制日志记录都先cache，提交时写入。

所以，对于事务表来说，一个事务中可能包含多条二进制日志事件，它们会在提交时一次性写入。而对于非事务表的操作，每次执行完语句就直接写入。

MariaDB/MySQL默认没有启动二进制日志，要启用二进制日志使用–log-bin=[on|off|file_name]选项指定，如果没有给定file_name，则默认为datadir下的主机名加"-bin"，并在后面跟上一串数字表示日志序列号，如果给定的日志文件中包含了后缀(logname.suffix)将忽略后缀部分。

或者在配置文件中的[mysqld]部分设置log-bin也可以。注意：对于mysql 5.7，直接启动binlog可能会导致mysql服务启动失败，这时需要在配置文件中的mysqld为mysql实例分配server_id。

mysqld还创建一个二进制日志索引文件，当二进制日志文件滚动的时候会向该文件中写入对应的信息。所以该文件包含所有使用的二进制日志文件的文件名。默认情况下该文件与二进制日志文件的文件名相同，扩展名为'.index'。要指定该文件的文件名使用–log-bin-index[=file_name]选项。当mysqld在运行时不应手动编辑该文件，免得mysqld变得混乱。

当重启mysql服务或刷新日志或者达到日志最大值时，将滚动二进制日志文件，滚动日志时只修改日志文件名的数字序列部分。

二进制日志文件的最大值通过变量max_binlog_size设置(默认值为1G)。但由于二进制日志可能是基于事务来记录的(如innodb表类型)，而事务是绝对不可能也不应该跨文件记录的，如果正好二进制日志文件达到了最大值但事务还没有提交则不会滚动日志，而是继续增大日志，所以max_binlog_size指定的值和实际的二进制日志大小不一定相等。

因为二进制日志文件增长迅速，但官方说明因此而损耗的性能小于1%，且二进制目的是为了恢复定点数据库和主从复制，所以出于安全和功能考虑，极不建议将二进制日志和datadir放在同一磁盘上。

5.2 查看二进制日志

MySQL中查看二进制日志的方法主要有几种。

1.使用mysqlbinlog工具。

2.使用show显示对应的信息。

5.2.1 mysqlbinlog

二进制日志可以使用mysqlbinlog命令查看。

以下是常用的几个选项：

-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可以查看

在进行测试之前，先对日志进行一次刷新，以方便解释二进制日志的信息。

假设现在的日志文件是mysql-bin.000001，里面暂时只有一些初始信息，没有记录任何操作过的记录。

下面是每个二进制日志文件的初始信息。可以看到记录了时间和位置信息(at 4)。

现在在数据库中执行下面的操作：

再查看二进制日志信息。

将上述信息整理为下图：其中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查看简化的日志文件。

比较这两个文件，看看简化的日志文件简化了哪些东西。

从上图中可以看出，使用-s后，少了基于行的日志信息，也少了记录的位置和时间信息。

使用-o可以忽略前N个条目，例如上面的操作涉及了6个操作。忽略掉前3个后的日志显示如下：可以看到直接从位置441开始显示了。

使用-d可以只显示指定数据库相关的操作。例如先切换到其他数据库进行一番操作，然后再使用-d查看日志。

可以看到，除了指定的mysql数据库的信息输出了，还非常简化的输出了其他数据库的信息。

mysqlbinlog最有用的两个选项就是指定时间和位置来输出日志。

指定时间时，将输出指定时间范围内的日志。指定的时间可以不和日志中记录的日志相同。

同理指定位置也一样，但是指定位置时有个要求是如果指定起始位置，则必须指定日志文件中明确的起始位置。例如，日志文件中有位置120、305、441，可以指定起始和结束位置为120、500，但是不可以指定起止位置为150、500，因为日志文件中不存在150这个位置。

5.2.2 show binary logs

该语句用于查看当前使用了哪些二进制日志文件。

可以通过查看二进制的index文件来查看当前正在使用哪些二进制日志。

也可以在mysql环境中使用show {binary | master} logs来查看。binary和master是同义词。

5.2.3 show binlog events

该语句用于查看日志中进行了哪些操作。

可以指定起始位置。同样，起始位置必须指定正确，不能指定不存在的位置。

5.2.4 show master status

该语句用于显示主服务器中的二进制日志信息。如果是主从结构，它只会显示主从结构中主服务器的二进制日志信息。

可以查看到当前正在使用的日志及下一事件记录的开始位置，还能查看到哪些数据库需要记录二进制日志，哪些数据库不记录二进制日志。

5.3 删除二进制日志

删除二进制日志有几种方法。不管哪种方法，都会将删除后的信息同步到二进制index文件中。

1.reset master将会删除所有日志，并让日志文件重新从000001开始。

2.PURGE { BINARY | MASTER } LOGS { TO 'log_name' | BEFORE datetime_expr }

purge master logs to "binlog_name.00000X"将会清空00000X之前的所有日志文件。例如删除000006之前的日志文件。