日志文件记录了影响 MySQL数据库的各种类型活动。 MySQL数据库中常见的日志文件有:
- 错误日志(error log)
- 二进制日志(binlog)
- 慢查询日志(slow query log)
- 查询日志(log)
这些日志文件可以帮助DBA对 MySQL数据库的运行状态进行诊断,从而更好地进行数据库层面的优化。
1、错误日志
错误日志文件对 MySQL的启动、运行、关闭过程进行了记录。 MySQL DBA在遇到问题时应该首先查看该文件以便定位问题。该文件不仅记录了所有的错误信息,也记录一些警告信息或正确的信息。用户可以通过命令SHOW VARIABLES LIKE 'log_error'来定位该文件,如
mysql> SHOW VARIABLES LIKE 'log_error';
+---------------+----------------------------------------+
| Variable_name | Value |
+---------------+----------------------------------------+
| log_error | /usr/local/mysql/data/mysqld.local.err |
+---------------+----------------------------------------+
1 row in set (0.00 sec)
当出现MySQL数据库不能正常启动时,第一个必须查找的文件应该就是错误日志文件,该文件记录了错误信息,能很好地指导用户发现问题。当数据库不能重启时,通过查错误日志文件可以得到如下内容:
这里,错误日志文件提示了找不到权限库 mysql,所以启动失败。有时用户可以直接在错误日志文件中得到优化的帮助,因为有些警告(warning)很好地说明了问题所在。而这时可以不需要通过查看数据库状态来得知,例如,下面的错误文件中的信息可能告诉用户需要增大 InnoDB存储引擎的 redo log:
2、慢查询日志
可以通过错误日志得到一些关于数据库优化的信息,而慢查询日志(slow log)可帮助DBA定位可能存在问题的SQL语句,从而进行SQL语句层面的优化。例如,可以在 MySQL启动时设一个阈值,将运行时间超过该值的所有SQL语句都记录到慢查询日志文件中。DBA每天或每过一段时间对其进行检查,确认是否有SQL语句需要进行优化。该阈值可以通过参数 long_query_time来设置,默认值为10,代表10秒。
在默认情况下, MySQL数据库并不启动慢查询日志,用户需要手工将这个参数设为ON:
mysql> SHOW VARIABLES LIKE 'long_query_time';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)
mysql> SHOW VARIABLES LIKE 'log_slow_queries';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| log_slow_queries| ON |
+-----------------+-----------+
mysql5.6版本以上，取消了参数log_slow_queries，更改为slow_query_log，还需要加上 slow_query_log = on 否则，还是没用。
mysql> SHOW VARIABLES LIKE 'slow_query_log';
+----------------+-------+
| Variable_name | Value |
+----------------+-------+
| slow_query_log | OFF |
+----------------+-------+
1 row in set (0.00 sec)
mysql> SHOW VARIABLES LIKE 'slow_query_log_file';
+---------------------+------------------------------------------------------+
| Variable_name | Value |
+---------------------+------------------------------------------------------+
| slow_query_log_file | /usr/local/mysql/data/my-computer-slow.log |
+---------------------+------------------------------------------------------+
这里有两点需要注意。首先,设置 long_query_time这个阈值后, MySQL数据库会记录运行时间超过该值的所有SQL语句,但运行时间正好等于 long_query_time的情况并不会被记录下。也就是说,在源代码中判断的是大于long_query_time,而非大于等于。其次,从 MySQL5.1开始, long_query_time开始以微秒记录SQL语句运行的时间,之前仅用秒为单位记录。而这样可以更精确地记录SQL的运行时间,供DBA分析。对DBA来说,一条SQL语句运行0.5秒和0.05秒是非常不同的,前者可能已经进行了表扫,后面可能是进行了索引。
另一个和慢查询日志有关的参数是 log_queries_not_using_indexes,如果运行的SQL语句没有使用索引,则 MySQL数据库同样会将这条SQL语句记录到慢查询日志文件。
首先确认打开了log_queries_not_using_indexes：
mysql> SHOW VARIABLES LIKE 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | ON |
+-------------------------------+-------+
1 row in set (0.00 sec)
My SQL5.6.5版本开始新增了一个参数 log_throttle_queries_not_using_indexes,用来表示每分钟允许记录到 slow log的且未使用索引的SQL语句次数。该值默认为0,表示没有限制。在生产环境下,若没有使用索引,此类SQL语句会频繁地被记录到slow log,从而导致 slow log文件的大小不断增加,故DBA可通过此参数进行配置。
mysql> SHOW VARIABLES LIKE 'log_throttle_queries_not_using_indexes';
+----------------------------------------+-------+
| Variable_name | Value |
+----------------------------------------+-------+
| log_throttle_queries_not_using_indexes | 0 |
+----------------------------------------+-------+
1 row in set (0.00 sec)
DBA可以通过慢查询日志来找出有问题的SQL语句,对其进行优化。然而随着MySQL数据库服务器运行时间的增加,可能会有越来越多的SQL查询被记录到了慢查询日志文件中,此时要分析该文件就显得不是那么简单和直观的了。而这时 MySQL数据库提供的 mysqldumpslow命令,可以很好地帮助DBA解决该问题。
如果用户希望得到执行时间最长的10条SQL语句,可以运行如下命令:
mysqldumpslow -s al -n l0 david.log
MySQL5.1开始可以将慢查询的日志记录放入一张表中,这使得用户的查询更加方便和直观。慢查询表在mysql架构下,名为 slow_log,其表结构定义如下:
mysql> show create table mysql.slow_log\G
*************************** 1. row ***************************
Table: slow_log
Create Table: CREATE TABLE `slow_log` (
`start_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
`user_host` mediumtext NOT NULL,
`query_time` time(6) NOT NULL,
`lock_time` time(6) NOT NULL,
`rows_sent` int(11) NOT NULL,
`rows_examined` int(11) NOT NULL,
`db` varchar(512) NOT NULL,
`last_insert_id` int(11) NOT NULL,
`insert_id` int(11) NOT NULL,
`server_id` int(10) unsigned NOT NULL,
`sql_text` mediumblob NOT NULL,
`thread_id` bigint(21) unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'
1 row in set (0.00 sec)
参数 log_output指定了慢查询输出的格式,默认为FILE,可以将它设为 TABLE,然后就可以查询 mysql架构下的slow_log表了,如:
mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output | FILE |
+---------------+-------+
1 row in set (0.00 sec)
mysql> set global log_output='TABLE';
Query OK, 0 rows affected (0.01 sec)
mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output | TABLE |
+---------------+-------+
1 row in set (0.00 sec)
mysql> select sleep(11);
+-----------+
| sleep(11) |
+-----------+
| 0 |
+-----------+
1 row in set (10.02 sec)
mysql> select * from mysql.slow_log\G
*************************** 1. row ***************************
start_time: 2018-10-09 15:36:30.948543
user_host: root[root] @ localhost []
query_time: 00:00:11.001354
lock_time: 00:00:00.000000
rows_sent: 1
rows_examined: 0
db: information_schema
last_insert_id: 0
insert_id: 0
server_id: 0
sql_text: select sleep(11)
thread_id: 4
1 row in set (0.00 sec)
参数 log_output是动态的,并且是全局的,因此用户可以在线进行修改。在上表中人为设置了睡眠(sleep)10秒,那么这句SQL语句就会被记录到 slow_log表了。
查看 slow_log表的定义会发现该表使用的是CSV引擎,对大数据量下的查询效率可能不高。用户可以把 slow_log表的引擎转换到 MyISAM,并在 start_time列上添加索引以进一步提高査询的效率。但是,如果已经启动了慢查询,将会提示错误:
mysql>ALTER TABLE mysql.slow_log ENGINE=MyISM;
ERROR 1580 (HY000): You cannot 'ALTER a log table if logging is enabled
mysql>SET GLOBAL slow query log=off;
Query OK, 0 rows affected (0.00 sec)
mysql>ALTER TABLE mysql slow log ENGINE=MyISAM;
Query OK,1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0
不能忽视的是,将 slow_log表的存储引擎更改为MyAM后,还是会对数据库造成额外的开销。不过好在很多关于慢查询的参数都是动态的,用户可以方便地在线进行设置或修改。
MySQL的 slow_log通过运行时间来对SQL语句进行捕获,这是一个非常有用的优化技巧。但是当数据库的容量较小时,可能因为数据库刚建立,此时非常大的可能是数据全部被缓存在缓冲池中,SQL语句运行的时间可能都是非常短的,一般都是0.5秒。
InnoSQL版本加强了对于SQL语句的捕获方式。在原版 MySQL的基础上在slow log中增加了对于逻辑读取(logical reads)和物理读取(physical reads)的统计。这里的物理读取是指从磁盘进行IO读取的次数,逻辑读取包含所有的读取,不管是磁盘还是缓冲池。例如
从上面的例子可以看到该子查询的逻辑读取次数是91584次,物理读取为19次。从逻辑读与物理读的比例上看,该SQL语句可进行优化。
用户可以通过额外的参数 long_query_io将超过指定逻辑IO次数的SQL语句记录到slow log中。该值默认为100,即表示对于逻辑读取次数大于100的SQL语句,记录到slow log中。而为了兼容原 MySQL数据库的运行方式,还添加了参数 slow_query_type,用来表示启用 slow log的方式,可选值为:
- 0表示不将SQL语句记录到 slow log
- 1表示根据运行时间将SQL语句记录到 slow log
- 2表示根据逻辑IO次数将SQL语句记录到 slow log
- 3表示根据运行时间及逻辑IO次数将SQL语句记录到 slow log
3、查询日志
查询日志记录了所有对 MySQL数据库请求的信息,无论这些请求是否得到了正确的执行。默认文件名为:主机名.log。如查看一个查询日志路径:
mysql> SHOW VARIABLES LIKE 'general_log%';
+------------------+-------------------------------------------------+
| Variable_name | Value |
+------------------+-------------------------------------------------+
| general_log | OFF |
| general_log_file | /usr/local/mysql/data/my-computer.log |
+------------------+-------------------------------------------------+
2 rows in set (0.00 sec)
查询日志。它记录所有MySQL活动，在诊断问题是非常有用。日志文件可能会很快的变得非常大，因此不应该长期使用它。此日志通常名为hostname.log。
同样地,从 MySQL5.1开始,可以将查询日志的记录放入mysq架构下的 general_log表中,该表的使用方法和前面小节提到的 slow log基本一样,这里不再赘述。
4、二进制日志
二进制日志(binary log)记录了对 MySQL数据库执行更改的所有操作,但是不包括 SELECT和SHOW这类操作,因为这类操作对数据本身并没有修改。然而,若操作本身并没有导致数据库发生变化,那么该操作可能也会写入二进制日志。例如:
从上述例子中可以看到, MySQL数据库首先进行 UPDATE操作,从返回的结果看到 Changed为0,这意味着该操作并没有导致数据库的变化。但是通过命令SHOW BINLOG EVENT可以看出在二进制日志中的确进行了记录。
如果用户想记录 SELECT和SHOW操作,那只能使用查询日志,而不是二进制日志。此外,二进制日志还包括了执行数据库更改操作的时间等其他额外信息。总的来说,二进制日志主要有以下几种作用。
- 恢复(recovery):某些数据的恢复需要二进制日志,例如,在一个数据库全备文件恢复后,用户可以通过二进制日志进行 point-in-time的恢复。
- 复制(replication):其原理与恢复类似,通过复制和执行二进制日志使一台远程的 MySQL数据库(一般称为slave或 standby)与一台 MySQL数据库(一般称为 master或 primary)进行实时同步。
- 审计(audit):用户可以通过二进制日志中的信息来进行审计,判断是否有对数据库进行注入的攻击。
查看到binlog日志为OFF关闭状态：
mysql> show variables like 'log_bin';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_bin | OFF |
+---------------+-------+
1 row in set (0.00 sec)
通过配置参数 log-bin[=name]可以启动二进制日志。
退出MySQL，使用vi编辑器修改MySQL的my.cnf配置文件。
server-id表示单个结点的id，这里由于只有一个结点，所以可以把id随机指定为一个数，这里将id设置成1。若集群中有多个结点，则id不能相同， 第二句是指定binlog日志文件的名字为mysql-bin，以及其存储路径。
此时再次进入MySQL，查看binlog日志的状态。显示binlog日志为ON开启状态。
如果不指定name则默认二进制日志文件名为主机名,后缀名为二进制日志的序列号,所在路径为数据库所在目录( datadir)。如：
这里的 bin_log.00001即为二进制日志文件,我们在配置文件中指定了名字,所以没有用默认的文件名。 bin_log.index为二进制的索引文件,用来存储过往产生的二进制日志序号,在通常情况下,不建议手工修改这个文件。
二进制日志文件在默认情况下并没有启动,需要手动指定参数来启动。可能有人会质疑,开启这个选项是否会对数据库整体性能有所影响。不错,开启这个选项的确会影响性能,但是性能的损失十分有限。根据 MySQL官方手册中的测试表明,开启二进制日志会使性能下降1%但考虑到可以使用复制( replication)和 point-in-time的恢复,这些性能损失绝对是可以且应该被接受的。
以下配置文件的参数影响着二进制日志记录的信息和行为:
- max_binlog_size
- binlog_cache_size
- sync_binlog
- binlog_do_db
- binlog_ignore_db
- log_slave_update
- binlog_format
参数 max_binlog_size指定了单个二进制日志文件的最大值,如果超过该值,则产生新的二进制日志文件,后缀名+1,并记录到 index文件。从 MySQL5.0开始的默认值为1073741824,代表1G(在之前版本中 max_binlog_size默认大小为1.1G)。
当使用事务的表存储引擎(如 InnodB存储引擎)时,所有未提交( uncommitted)的二进制日志会被记录到一个缓存中去,等该事务提交(committed)时直接将缓冲中的二进制日志写入二进制日志文件,而该缓冲的大小由 binlog_cache_size决定,默认大小为32K。此外, binlog_cache_size是基于会话( session)的,也就是说,当一个线程开始一个事务时,MyQL会自动分配一个大小为 binlog_cache_size的缓存,因此该值的设置需要相当小心,不能设置过大。当一个事务的记录大于设定的 binlog_cache_size时, MySQL会把缓冲中的日志写人一个临时文件中,因此该值又不能设得太小。通过SHOW GLOBAL STATUS命令查看 binlog_cache_use、 binlog_cache_disk_use的状态,可以判断当前 binlog_cache_size的设置是否合适。 binlog_cache_use记录了使用缓冲写进制日志的次数, binlog_cache_disk_use记录了使用临时文件写二进制日志的次数。现在来看一个数据库的状态:
使用缓冲次数为33553,临时文件使用次数为0。看来32KB的缓冲大小对于当前这个 MySQL数据库完全够用,暂时没有必要增加 binlog_cache_size的值。
在默认情况下,二进制日志并不是在每次写的时候同步到磁盘(用户可以理解为缓冲写)。因此,当数据库所在操作系统发生宕机时,可能会有最后一部分数据没有写入二进制日志文件中,这会给恢复和复制带来问题。参数 sync_binlog=[N]表示每写缓冲多少次就同步到磁盘。如果将N设为1,即 sync_binlog=1表示采用同步写磁盘的方式来写二进制日志,这时写操作不使用操作系统的缓冲来写二进制日志。 sync_binlog的默认值为0,如果使用 InnoDB存储引擎进行复制,并且想得到最大的高可用性,建议将该值设为ON。不过该值为ON时,确实会对数据库的IO系统带来一定的影响。
但是,即使将 sync_binlog设为1,还是会有一种情况导致问题的发生。当使用InnoDB存储引擎时,在一个事务发出 COMMIT动作之前,由于 sync_binlog为1,因此会将二进制日志立即写入磁盘。如果这时已经写人了二进制日志,但是提交还没有发生,并且此时发生了宕机,那么在 MySQL数据库下次启动时,由于 COMMIT操作并没有发生,这个事务会被回滚掉。但是二进制日志已经记录了该事务信息,不能被回滚。这个问题可以通过将参数 innodb_support_xa设为1来解决,虽然 innodb_support_xa与XA事务有关,但它同时也确保了二进制日志和 InnoDB存储引擎数据文件的同步。
参数 binlog-do-db和 binlog-ignore-db表示需要写入或忽略写入哪些库的日志。默认为空,表示需要同步所有库的日志到二进制日志。
如果当前数据库是复制中的 slave角色,则它不会将从 master取得并执行的二进制日志写入自己的二进制日志文件中去。如果需要写人,要设置log-slave-update。如果需要搭建 master=> slave=> slave架构的复制,则必须设置该参数。
binlog_format参数十分重要,它影响了记录二进制日志的格式。在 MySQL5.1版本之前,没有这个参数。所有二进制文件的格式都是基于SQL语句(statement)级别的,因此基于这个格式的二进制日志文件的复制( Replication)和 Oracle的逻辑 Standby有点相似。同时,对于复制是有一定要求的。如在主服务器运行rand、uuid等函数,又或者使用触发器等操作,这些都可能会导致主从服务器上表中数据的不一致(not sync)另一个影响是,会发现 InnoDB存储引擎的默认事务隔离级别是 REPEATABLE READ。
这其实也是因为二进制日志文件格式的关系,如果使用 READ COMMITTED的事务隔离级别(大多数数据库,如 Oracle, Microsoft SQL Server数据库的默认隔离级别),会出现类似丢失更新的现象,从而出现主从数据库上的数据不一致。
MySQL5.1开始引入了 binlog_format参数,该参数可设的值有 STATEMENT、ROW和 MIXED。
(1)STATEMENT格式和之前的 MySQL版本一样,二进制日志文件记录的是日志的逻辑SQL语句。
(2)在ROW格式下,二进制日志记录的不再是简单的SQL语句了,而是记录表的行更改情况。基于ROW格式的复制类似于 Oracle的物理 Standby(当然,还是有些区别)。同时,对上述提及的 Statement格式下复制的问题予以解决。从 MySQL5.1版本开始,如果设置了 binlog_format为ROW,可以将 InnoDB的事务隔离基本设为READ COMMITTED,以获得更好的并发性。
(3)在MXED格式下, MySQL默认采用 STATEMENT格式进行二进制日志文件的记录,但是在一些情况下会使用ROW格式,可能的情况有:
- 1)表的存储引擎为NDB,这时对表的DML操作都会以ROW格式记录。
- 2)使用了UUID()、 USER()、 CURRENT_USER()、 FOUND_ROWS()、 ROW_COUNT()
- 等不确定函数。
- 3)使用了 INSERT DELAY语句。
- 4)使用了用户定义函数(UDF)
- 5)使用了临时表(temporary table)
此外, binlog_format参数还有对于存储引擎的限制,如表所示。
| 存储引擎 | Row格式 | Statement格式 |
|---|---|---|
| 存储引擎 | Row格式 | Statement格式 |
| InnoDB | Yes | Yes |
| MyISAM | Yes | Yes |
| HEAP | Yes | Yes |
| MERGE | Yes | Yes |
| NDB | Yes | No |
| Archive | Yes | Yes |
| CSV | Yes | Yes |
| Federate | Yes | Yes |
| Blockhole | No | Yes |
binlog_format是动态参数,因此可以在数据库运行环境下进行更改,例如,我们可以将当前会话的 binlog_format设为ROW,如:
mysql> SET @@session.binlog_format='ROW';
Query OK, 0 rows affected (0.00 sec)
mysql> select @@session.binlog_format;
+-------------------------+
| @@session.binlog_format |
+-------------------------+
| ROW |
+-------------------------+
1 row in set (0.00 sec)
当然,也可以将全局的 binlog_format设置为想要的格式,不过通常这个操作会带来问题,运行时要确保更改后不会对复制带来影响。如:
mysql> SET @@global.binlog_format='ROW';
Query OK, 0 rows affected (0.00 sec)
mysql> select @@global.binlog_format;
+------------------------+
| @@global.binlog_format |
+------------------------+
| ROW |
+------------------------+
1 row in set (0.00 sec)
在通常情况下,我们将参数 binlog_format设置为ROW,这可以为数据库的恢复和复制带来更好的可靠性。但是不能忽略的一点是,这会带来二进制文件大小的增加,有些语句下的ROW格式可能需要更大的容量。比如我们有两张一样的表,大小都为100W,分别执行 UPDATE操作,观察二进制日志大小的变化:
可以看到,在 binlog format格式为 STATEMENT的情况下,执行 UPDATE语句后二进制日志大小只增加了200字节(306-106)。如果使用ROW格式,同样对t2表进行操作,可以看到:
这时会惊讶地发现,同样的操作在ROW格式下竟然需要13782094字节,二进制日志文件的大小差不多增加了13MB,要知道t2表的大小也不超过17MB。而且执行时间也有所增加(这里我设置了sync_binlog=1)。这是因为这时 MySQL数据库不再将逻辑的SQL操作记录到二进制日志中,而是记录对于每行的更改。
上面的这个例子告诉我们,将参数 binlog_format设置为ROW,会对磁盘空间要求有一定的增加。而由于复制是采用传输二进制日志方式实现的,因此复制的网络开销也有所增加。
进制日志文件的文件格式为二进制(好像有点废话),不能像错误日志文件、慢查询日志文件那样用cat、head、tail等命令来查看。要查看二进制日志文件的内容,必须通过 MySQL提供的工具 mysqlbinlog。对于 STATEMENT格式的二进制日志文件,在使用 mysqlbinlog后,看到的就是执行的逻辑SQL语句,如:
通过SQL语句 UPDATE t2 SET username= UPPER( username) WHERE id=1可以看到,二进制日志的记录采用SQL语句的方式。在这种情况下, mysqlbinlog和 Oracle LogMiner类似。但是如果这时使用ROW格式的记录方式,会发现 mysqlbinlog的结果变得“不可读”( unreadable),如:
这里看不到执行的SQL语句,反而是一大串用户不可读的字符。其实只要加上参数或-vv就能清楚地看到执行的具体信息了。-vv会比-v多显示出更新的类型。加上-vv选项,可以得到:
现在 mysqlbinlog向我们解释了它具体做的事情。可以看到,一句简单的 update t2 set username= upper( username) where id=1语句记录了对于整个行更改的信息,这也解释了为什么前面更新了10W行的数据,在ROW格式下,二进制日志文件会增大13MB。
