MYSQL数据库的日志文件

日志文件：用来记录MySQL实例对某种条件做出响应时写入的文件。如错误日志文件、二进制日志文件、慢查询日志文件、查询日志文件等。

错误日志

show variables like 'log_error';

system hostname;

可以看到错误文件的路径和文件名，默认情况下错误文件的文件名为服务器的主机名。当出现MySQL数据库不能正常启动时，第一个必须查找的文件应该就是错误日志文件，该文件记录了出错信息，能很好地指导我们找到问题。

慢查询日志

慢查询能为SQL语句的优化带来很好的帮助。可以设一个阈值，将运行时间超过该值的所有SQL语句都记录到慢查询日志文件中。该阈值可以通过参数long_query_time来设置，默认值为10，代表10秒。默认情况下，MySQL数据库并不启动慢查询日志，你需要手工将这个参数设为ON，然后启动，可以看到如下结果：

show variables like '%long_query%';

show variables like 'slow_query_log%';

set global slow_query_log=ON;

这里需要注意两点。首先，设置long_query_time这个阈值后，MySQL数据库会记录运行时间超过该值的所有SQL语句，但对于运行时间正好等于long_query_time的情况，并不会被记录下。也就是说，在源代码里是判断大于long_query_time，而非大于等于。其次，从MySQL 5.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：

show variables like 'log_queries_not_using_indexes';

日志查看和分析

这里详细记录了SQL语句的信息，如上述SQL语句运行的账户和IP、运行时间、锁定的时间、返回行等。我们可以通过慢查询日志来找出有问题的SQL语句，对其进行优化。随着MySQL数据库服务器运行时间的增加，可能会有越来越多的SQL查询被记录到了慢查询日志文件中，这时要分析该文件就显得不是很容易了。MySQL这时提供的mysqldumpslow命令，可以很好地解决这个问题：

[root@nh122-190 data]#mysqldumpslow nh122-190-slow.log
Reading mysql slow query log from nh122-190-slow.log
Count：11 Time=10.00s（110s）Lock=0.00s（0s）Rows=0.0（0），
dbother[dbother]@localhost
insert into test.DbStatus select now（），（N-com_select）/（N-uptime），（N-
com_insert）/（N-uptime），（N-com_update）/（N-uptime），（N-com_delete）/（N-uptime），N-
（N/N），N-（N/N），N.N/N，N-N/（N*N），GetCPULoadInfo（N）from test.CheckDbStatus order by
check_id desc limit N
Count：653 Time=0.00s（0s）Lock=0.00s（0s）Rows=0.0（0），9YOUgs_SC[9YOUgs_SC]@
[192.168.43.7]
select custom_name_one from'low_game_schema'.'role_details'where role_id='S'
rse and summarize the MySQL slow query log.Options are
--verbose verbose
--debug debug
--help write this text to standard output
-v verbose
-d debug
-s ORDER what to sort by（al，at，ar，c，l，r，t），'at'is default
al：average lock time
ar：average rows sent
at：average query time
c：count
l：lock time
r：rows sent
t：query time
-r reverse the sort order（largest last instead of first）
-t NUM just show the top n queries
-a don't abstract all numbers to N and strings to'S'
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep：only consider stmts that include this string
-h HOSTNAME hostname of db server for*-slow.log filename（can be wildcard），
default is'*'，i.e.match all
-i NAME name of server instance（if using mysql.server startup script）
-l don't subtract lock time from total time

如果我们想得到锁定时间最长的10条SQL语句，可以运行：

[root@nh119-141 data]#/usr/local/mysql/bin/mysqldumpslow -s al-n 10 david.log
Reading mysql slow query log from david.log
Count：5 Time=0.00s（0s）Lock=0.20s（1s）Rows=4.4（22），Audition
[Audition]@[192.168.30.108]
SELECT OtherSN，State FROM wait_friend_info WHERE UserSN=N
Count：1 Time=0.00s（0s）Lock=0.00s（0s）Rows=1.0（1），audition-kr[audition-
kr]@[192.168.30.105]
SELECT COUNT（N）FROM famverifycode WHERE UserSN=N AND verifycode='S'
……

MySQL 5. 1开始可以将慢查询的日志记录放入一张表中，这使我们的查询更加直观。慢查询表在mysql架构下，名为slow_log。其表结构定义如下：

mysql＞show create table mysql.slow_log；
***************************1.row***************************
Table：slow_log
Create Table：CREATE TABLE'slow_log'（
'start_time'timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE
CURRENT_TIMESTAMP，
'user_host'mediumtext NOT NULL，
'query_time'time NOT NULL，
'lock_time'time 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（11）NOT NULL，
'sql_text'mediumtext NOT NULL
）ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'

参数log_output指定了慢查询输出的格式，默认为FILE，你可以将它设为TABLE，然后就可以查询mysql架构下的slow_log表了，如：

show variables like 'log_output';

set global log_output='TABLE';

show variables like 'log_output';

select sleep (10);

select * from mysql.slow_log\G

参数log_output是动态的，并且是全局的。我们可以在线进行修改。在上表中我设置了睡眠（sleep）10秒，那么这句SQL语句就会被记录到slow_log表了。

查看slow_log表的定义会发现，该表使用的是CSV引擎，对大数据量下的查询效率可能不高。我们可以把slow_log表的引擎转换到MyISAM，用来进一步提高查询的效率。但是，如果已经启动了慢查询，将会提示错误：

mysql＞alter table mysql.slow_log engine=myisam；
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表的存储引擎更改为MyISAM后，对数据库还是会造成额外的开销。不过好在很多关于慢查询的参数都是动态的，我们可以方便地在线进行设置或者修改。

查询日志

查询日志记录了所有对MySQL数据库请求的信息，不论这些请求是否得到了正确的执行。默认文件名为：主机名.log。我们查看一个查询日志：

[root@nineyou0-43 data]#tail nineyou0-43.log
090925 11：00：24 44 Connect zlm@192.168.0.100 on
44 Query SET AUTOCOMMIT=0
44 Query set autocommit=0
44 Quit
090925 11：02：37 45 Connect Access denied for user'root'@'localhost'（using
password：NO）
090925 11：03：51 46 Connect Access denied for user'root'@'localhost'（using
password：NO）
090925 11：04：38 23 Query rollback

通过上述查询日志你会发现，查询日志甚至记录了对access denied的请求。同样，从MySQL 5.1开始，可以将查询日志的记录放入mysql架构下的general_log表，该表的使用方法和前面小节提到的slow_log基本一样。

set global general_log=ON;

set global log_output='TABLE';

二进制日志

二进制日志记录了对数据库执行更改的所有操作，但是不包括SELECT和SHOW这类操作，因为这类操作对数据本身并没有修改，如果你还想记录SELECT和SHOW操作，那只能使用查询日志，而不是二进制日志了。此外，二进制还包括了执行数据库更改操作的时间和执行时间等信息。二进制日志主要有以下两种作用：

恢复（recovery）。某些数据的恢复需要二进制日志，如当一个数据库全备文件恢复后，我们可以通过二进制日志进行point-in-time的恢复。
复制（replication）。其原理与恢复类似，通过复制和执行二进制日志使得一台远程的MySQL数据库（一般称为slave或者standby）与一台MySQL数据库（一般称为master或者primary）进行实时同步。

通过配置参数log_bin[=name]可以启动二进制日志。如果不指定name，则默认二进制日志文件名为主机名，后缀名为二进制日志的序列号，所在路径为数据库所在目录（datadir）如：

show variables like '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-ingore-db
log-slave-update
binlog_format

max_binlog_size:参数max_binlog_size指定了单个二进制日志文件的最大值，如果超过该值，则产生新的二进制日志文件，后缀名+1，并记录到.index文件。从MySQL 5.0开始的默认值为1 073 741 824，代表1GB（之前的版本max-binlog-size默认大小为1.1GB）。

binlog_cache_size:当使用事务的表存储引擎（如InnoDB存储引擎）时，所有未提交（uncommitted）的二进制日志会被记录到一个缓存中，等该事务提交时（committed）时直接将缓冲中的二进制日志写入二进制日志文件，而该缓冲的大小由binlog_cache_size决定，默认大小为32KB。此外，binlog_cache_size是基于会话（session）的，也就是说，当一个线程开始一个事务时，MySQL会自动分配一个大小为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记录了使用临时文件写二进制日志的次数。现在来看一个数据库的状态：

show variables like 'binlog_cache_size';

show global status like 'binlog_cache%';

使用缓冲次数0次，临时文件使用次数为0。看来，32KB的缓冲大小对于当前这个MySQL数据库完全够用，所以暂时没有必要增加binlog_cache_size的值。

sync_binlog:默认情况下，二进制日志并不是在每次写的时候同步到磁盘（我们可以理解为缓冲写）。因此，当数据库所在操作系统发生宕机时，可能会有最后一部分数据没有写入二进制日志文件中。这会给恢复和复制带来问题。参数sync_binlog=[N]表示每写缓冲多少次就同步到磁盘。如果将N设为1，即sync_binlog=1表示采用同步写磁盘的方式来写二进制日志，这时写操作不使用操作系统的缓冲来写二进制日志。该默认值为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:参数binlog_do_db和binlog_ignore_db表示需要写入或者忽略写入哪些库的日志。默认为空，表示需要将所有库的日志同步到二进制日志。如果当前数据库是复制中的slave角色，则它不会将从master取得并执行的二进制日志写入自己的二进制日志文件中。如果需要写入，则需要设置log-slave-update。如果你需要搭建master=＞slave=＞slave架构的复制，则必须设置该参数。

binlog_format:这影响了记录二进制日志的格式。在MySQL 5.1版本之前，没有这个参数。所有二进制文件的格式都是基于SQL语句（statement）级别的，因此基于这个格式的二进制日志文件的复制（Replication）和Oracle逻辑Standby有点相似。同时，对于复制是有一定要求的如rand、uuid等函数，或者有使用触发器等可能会导致主从服务器上表的数据不一致（not sync），这可能使得复制变得没有意义。另一个影响是，你会发现InnoDB存储引擎的默认事务隔离级别是REPEATABLE READ。这其实也是因为二进制日志文件格式的关系，如果使用READ COMMITTED的事务隔离级别（大多数数据库，如Oracle、Microsoft SQL Server数据库的默认隔离级别）会出现类似丢失更新的现象，从而出现主从数据库上的数据不一致。

MySQL 5. 1开始引入了binlog_format参数，该参数可设的值有STATEMENT、ROW和MIXED。

（1）STATEMENT格式和之前的MySQL版本一样，二进制日志文件记录的是日志的逻辑SQL语句。

（2）在ROW格式下，二进制日志记录的不再是简单的SQL语句了，而是记录表的行更改情况。基于ROW格式的复制类似于Oracle的物理Standby（当然，还是有些区别）。同时，对于上述提及的Statement格式下复制的问题给予了解决。MySQL 5.1版本开始，如果设置了binlog_format为ROW，你可以将InnoDB的事务隔离基本设为READ COMMITTED，以获得更好的并发性。

（3）MIXED格式下，MySQL默认采用STATEMENT格式进行二进制日志文件的记录，但是在一些情况下会使用ROW格式，可能的情况有：

表的存储引擎为NDB，这时对于表的DML操作都会以ROW格式记录。
使用了UUID（）、USER（）、CURRENT_USER（）、FOUND_ROWS（）、ROW_COUNT（）等不确定函数。
使用了INSERT DELAY语句。
使用了用户定义函数（UDF）。
使用了临时表（temporary table）。

此外，binlog_format参数还有对于存储引擎的限制:

binlog_format是动态参数，因此可以在数据库运行环境下进行更改，例如，我们可以将当前会话的binlog_format设为ROW，如：

show variables like '%binlog_format%';

通常情况下，我们将参数binlog_format设置为ROW，这可以为数据库的恢复和复制带来更好的可靠性。但是不能忽略一点的是，这会带来二进制文件大小的增加，有些语句下的ROW格式可能需要更大的容量。

将参数binlog_format设置为ROW，对于磁盘空间要求有了一定的增加。而由于复制是采用传输二进制日志方式实现的，因此复制的网络开销也有了增加。

二进制日志文件的文件格式为二进制，不能像错误日志文件，慢查询日志文件用cat、head、tail等命令来查看。想要查看二进制日志文件的内容，须通过MySQL提供的工具mysqlbinlog。对于STATEMENT格式的二进制日志文件，使用mysqlbinlog后，看到就是执行的逻辑SQL语句，如：

[root@nineyou0-43 data]#mysqlbinlog --start -position=203 test.000004
/*！40019 SET@@session.max_insert_delayed_threads=0*/；
……
#090927 15：43：11 server id 1 end_log_pos 376 Query thread_id=188
exec_time=1 error_code=0
SET TIMESTAMP=1254037391/*！*/；
update t2 set username=upper（username）where id=1
/*！*/；
#at 376
#090927 15：43：11 server id 1 end_log_pos 403 Xid=1009
COMMIT/*！*/；
DELIMITER；
#End of log file
ROLLBACK/*added by mysqlbinlog*/；
/*！50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/；

update t2 set username=upper（username）where id=1，这个可以看到日志的记录以SQL语句的方式（为了排版的方便，省去了一些开始的信息）。在这个情况下，mysqlbinlog和Oracle LogMiner类似。但是如果这时使用ROW格式的记录方式，则会发现mysqlbinlog的结果变得“不可读”（unreadable），如：

[root@nineyou0-43 data]#mysqlbinlog --start -position=1065 test.000004
/*！40019 SET@@session.max_insert_delayed_threads=0*/；
……
#at 1135
#at 1198
#090927 15：53：52 server id 1 end_log_pos 1198 Table_map：'member'.'t2'mapped
to number 58
#090927 15：53：52 server id 1 end_log_pos 1378 Update_rows：table id 58 flags：
STMT_END_F
BINLOG'
EBq/ShMBAAAAPwAAAK4EAAAAADoAAAAAAAAABm1lbWJlcgACdDIACgMPDw/+CgsPAQwKJAAoAEAA
/gJAAAAA
EBq/ShgBAAAAtAAAAGIFAAAQADoAAAAAAAEACv////8A/AEAAAALYWxleDk5ODh5b3UEOXlvdSA3
Y2JiMzI1MmJhNmI3ZTljNDIyZmFjNTMzNGQyMjA1NAFNLacPAAAAAABjEnpxPBIAAAD8AQAAAAtB
TEVYOTk4OFlPVQQ5eW91IDdjYmIzMjUyYmE2YjdlOWM0MjJmYWM1MzM0ZDIyMDU0AU0tpw8AAAAA
AGMSenE8EgAA
'/*！*/；
#at 1378
#090927 15：53：52 server id 1 end_log_pos 1405 Xid=1110
COMMIT/*！*/；
DELIMITER；
#End of log file
ROLLBACK/*added by mysqlbinlog*/；
/*！50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/；
我们看不到执行的SQL语句，反而是一大串我们看不到的字符。其实只要加上参数-v或者-vv，就能清楚地看到执行的具体信息了，-vv会比-v多显示出更新的类型，这次我们加上-vv选项，得到：
[root@nineyou0-43 data]#mysqlbinlog -vv--start-position=1065 test.000004
……
BINLOG'
EBq/ShMBAAAAPwAAAK4EAAAAADoAAAAAAAAABm1lbWJlcgACdDIACgMPDw/+CgsPAQwKJAAoAEAA
/gJAAAAA
EBq/ShgBAAAAtAAAAGIFAAAQADoAAAAAAAEACv////8A/AEAAAALYWxleDk5ODh5b3UEOXlvdSA3
Y2JiMzI1MmJhNmI3ZTljNDIyZmFjNTMzNGQyMjA1NAFNLacPAAAAAABjEnpxPBIAAAD8AQAAAAtB
TEVYOTk4OFlPVQQ5eW91IDdjYmIzMjUyYmE2YjdlOWM0MjJmYWM1MzM0ZDIyMDU0AU0tpw8AAAAA
AGMSenE8EgAA
'/*！*/；
###UPDATE member.t2
###WHERE
###@1=1/*INT meta=0 nullable=0 is_null=0*/
###@2='david'/*VARSTRING（36）meta=36 nullable=0 is_null=0*/
###@3='family'/*VARSTRING（40）meta=40 nullable=0 is_null=0*/
###@4='7cbb3252ba6b7e9c422fac5334d22054'/*VARSTRING（64）meta=64 nullable=0
is_null=0*/
###@5='M'/*STRING（2）meta=65026 nullable=0 is_null=0*/
###@6='2009：09：13'/*DATE meta=0 nullable=0 is_null=0*/
###@7='00：00：00'/*TIME meta=0 nullable=0 is_null=0*/
###@8=''/*VARSTRING（64）meta=64 nullable=0 is_null=0*/
###@9=0/*TINYINT meta=0 nullable=0 is_null=0*/
###@10=2009-08-11 16：32：35/*DATETIME meta=0 nullable=0 is_null=0*/
###SET
###@1=1/*INT meta=0 nullable=0 is_null=0*/
###@2='DAVID'/*VARSTRING（36）meta=36 nullable=0 is_null=0*/
###@3=family/*VARSTRING（40）meta=40 nullable=0 is_null=0*/
###@4='7cbb3252ba6b7e9c422fac5334d22054'/*VARSTRING（64）meta=64 nullable=0
is_null=0*/
###@5='M'/*STRING（2）meta=65026 nullable=0 is_null=0*/
###@6='2009：09：13'/*DATE meta=0 nullable=0 is_null=0*/
###@7='00：00：00'/*TIME meta=0 nullable=0 is_null=0*/
###@8=''/*VARSTRING（64）meta=64 nullable=0 is_null=0*/
###@9=0/*TINYINT meta=0 nullable=0 is_null=0*/
###@10=2009-08-11 16：32：35/*DATETIME meta=0 nullable=0 is_null=0*/
#at 1378
#090927 15：53：52 server id 1 end_log_pos 1405 Xid=1110
COMMIT/*！*/；
DELIMITER；
#End of log file
ROLLBACK/*added by mysqlbinlog*/；
/*！50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/；

mysqlbinlog向我们解释了具体做的事情。可以看到，一句简单的update t2 set username=upper（username）where id=1语句记录为了对于整个行更改的信息，这也解释了为什么前面我们更新了10万行的数据，在ROW格式下，二进制日志文件会增大了13MB。

posted @ 2017-01-14 15:54 wade&luffy 阅读(4359) 评论(0) 编辑收藏举报

刷新页面返回顶部

wade&luffy

生活最主要的还是感受，坚持是一种刻意的练习，不断寻找缺点突破缺点的过程，而不是重复做某件事情。