日志文件:用来记录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。