MYSQL数据库的日志文件

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

错误日志

show variables like 'log_error';

system hostname;

MYSQL数据库的日志文件

可以看到错误文件的路径和文件名,默认情况下错误文件的文件名为服务器的主机名。当出现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;

MYSQL数据库的日志文件

 这里需要注意两点。首先,设置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';

MYSQL数据库的日志文件

日志查看和分析

这里详细记录了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 TableCREATE 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'int11NOT NULL'rows_examined'int11NOT NULL'db'varchar512NOT NULL'last_insert_id'int11NOT NULL'insert_id'int11NOT NULL'server_id'int11NOT 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

MYSQL数据库的日志文件

MYSQL数据库的日志文件

参数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 110024 44 Connect zlm@192.168.0.100 on
44 Query SET AUTOCOMMIT=0
44 Query set autocommit=0
44 Quit
090925 110237 45 Connect Access denied for user'root'@'localhost'(using
password:NO)
090925 110351 46 Connect Access denied for user'root'@'localhost'(using
password:NO)
090925 110438 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操作,那只能使用查询日志,而不是二进制日志了。此外,二进制还包括了执行数据库更改操作的时间和执行时间等信息。二进制日志主要有以下两种作用:

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

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

MYSQL数据库的日志文件

show variables like 'datadir';

MYSQL数据库的日志文件

 这里的bin_log.00001即为二进制日志文件,我们在配置文件中指定了名称,所以没有用默认的文件名。bin_log.index为二进制的索引文件,用来存储过往生产的二进制日志序号,通常情况下,不建议手工修改这个文件。

二进制日志文件在默认情况下并没有启动,需要你手动指定参数来启动。可能有人会质疑,开启这个选项是否会对数据库整体性能有所影响。不错,开启这个选项的确会影响性能,但是性能的损失十分有限。根据MySQL官方手册中的测试表明,开启二进制日志会使得性能下降1%。但考虑到可以使用复制(replication)和point-in-time的恢复,这些性能损失绝对是可以并且是应该被接受的。

以下配置文件的参数影响着二进制日志记录的信息和行为:

  1. max_binlog_size
  2. binlog_cache_size
  3. sync_binlog
  4. binlog-do-db
  5. binlog-ingore-db
  6. log-slave-update
  7. 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%'; 

MYSQL数据库的日志文件

使用缓冲次数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参数,该参数可设的值有STATEMENTROWMIXED

(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参数还有对于存储引擎的限制:

MYSQL数据库的日志文件

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

show variables like '%binlog_format%';

MYSQL数据库的日志文件

通常情况下,我们将参数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 154311 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 154311 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 155352 server id 1 end_log_pos 1198 Table_map:'member'.'t2'mapped
to number 58
#090927 155352 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 155352 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 163235/*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 163235/*DATETIME meta=0 nullable=0 is_null=0*/
#at 1378
#090927 155352 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。

 

上一篇:Java 学习杂记


下一篇:新版 OpenStack 首度支持 NFV 网络功能虚拟化