浅谈mysql日志

概述

日志文件是MySQL数据库的重要组成部分。MySQL有几种不同的日志文件，通常包括错误日志文件，二进制日志，通用日志，慢查询日志，等等。这些日志可以帮助我们定位mysqld内部发生的事件，数据库性能故障，记录数据的变更历史，用户恢复数据库等等。本文主要描述MySQL的各种日志文件。

MySQL日志文件分类

1.错误日志(Error Log)
2.二进制日志(Binary Log & Binary Log Index)
3.通用查询日志(query log)
4.慢查询日志(slow query log)
5.Innodb的在线 redo 日志(innodb redo log)、undo日志。
6.更新日志(update log) 

错误日志

错误日志记录了MyQL Server运行过程中所有较为严重的警告和错误信息,以及MySQL
Server 每次启动和关闭的详细信息。在默认情况下,系统记录错误日志的功能是关闭的, 错误信息被输出到标准错误输出(stderr) ,如果要开启系统记录错误日志的功能,需要在启动时开启-log-error 选项，也可以在配置文件中写入‘log-error[=/path/to/log_name]’。错误日志的默认存放位置在数据目录下,以hostname.err 命名。但是可以使用命令:—log-error[=file_name],修改其存放目录和文件名。
为了方便维护需要, 有时候会希望将错误日志中的内容做备份并重新开始记录, 这候时 就可以利用 MySQL 的 FLUSH LOGS 命令来告诉 MySQL 备份旧日志文件并生成新的日志文件。 备份文件名以“.old”结尾。

二进制日志

a、它包含的内容及作用如下：
包含了所有更新了数据或者已经潜在更新了数据(比如没有匹配任何行的一个DELETE)
包含关于每个更新数据库(DML)的语句的执行时间信息
不包含没有修改任何数据的语句，如果需要启用该选项，需要开启通用日志功能
主要目的是尽可能的将数据库恢复到数据库故障点，因为二进制日志包含备份后进行的所有更新
用于在主复制服务器上记录所有将发送给从服务器的语句
启用该选项数据库性能降低1%，但保障数据库完整性，对于重要数据库值得以性能换完整。有些类似于Oracle开启归档模式。
b、开启二进制日志的方法及属性
使用--log-bin[=file_name]选项或在配置文件中指定log-bin启动时，mysqld写入包含所有更新数据的SQL命令的日志文件。
对于未给出file_name值， 默认名为-bin后面所跟的主机名。
在未指定绝对路径的情形下，缺省位置保存在数据目录下。
每个二进制日志名会添加一个数字扩展名用于日志老化，因此不支持自定义的扩展名，会被mysql数字扩展名动态替换。
若当前的日志大小达到max_binlog_size，则自动创建新的二进制日志。
对于大的事务，二进制日志会超过max_binlog_size设定的值。也即是事务仅仅写入一个二进制日志。
由是可知，二进制日志文件大小接近，其size不是完全相等，这点不同于oracle。
二进制日志文件会有一个对应二进制日志索引文件，该文件包含所有的二进制日志，其文件名与二进制日志相同，扩展名为.index
二进制索引文件通过--log-bin-index[=file_name]选项来指定
RESET MASTER语句将删除所有二进制日志文件，这将影响到从库。也可以用PURGE MASTER LOGS只删除部分二进制文件。

日志记录格式：
基于“语句”记录；statement，默认模式。按照输入的语句记录日志，较于row模式，整表的修改可以减少大量的IO不会造成太多的IO压力，但是，语句中有存储过程或者函数等，部分函数在mysql的复制过程中无法执行。
基于“行”记录；row，按照行的变化来记录日志，优点不会记录sql上下文只会记录行的变化。缺点大量的表的修改会增加IO压力，降低数据库性能。
“混合” ：mixed，是以上两种level的混合使用，一般的语句修改使用statment格式保存binlog，如一些函数，statement无法完成主从复制的操作，则采用row格式保存binlog,MySQL会根据执行的每一条具体的sql语句来区分对待记录的日志形式，也就是在Statement和Row之间选择一种.新版本的MySQL中队row level模式也被做了优化，并不是所有的修改都会以row level来记录，像遇到表结构变更的时候就会以statement模式来记录。至于update或者delete等修改数据的语句，还是会记录所有行的变更。

查看二进制日志格式：

mysql> show variables like 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW   |
+---------------+-------+
1 row in set (0.01 sec)

设置二进制日志格式：

mysql> set @@binlog_format=MIXED;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | MIXED |
+---------------+-------+
1 row in set (0.00 sec)

在数据库中查看当前二进制日志：

mysql> show master status;    ##查看当前二进制日志
+-------------------+----------+--------------+------------------+-------------------+
| File              | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+-------------------+----------+--------------+------------------+-------------------+
| master-bin.000002 |      154 |              |                  |                   |
+-------------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

　mysql> show binary logs;      ##查看所有二进制日志
　+-------------------+-----------+
　| Log_name | File_size |
　+-------------------+-----------+
　| master-bin.000001 | 25087 |
　| master-bin.000002 | 1042 |
　+-------------------+-----------+
　2 rows in set (0.00 sec)

　mysql> show master logs;　　　　##查看所有二进制日志
　+-------------------+-----------+
　| Log_name | File_size |
　+-------------------+-----------+
　| master-bin.000001 | 25087 |
　| master-bin.000002 | 1042 |
　+-------------------+-----------+
　2 rows in set (0.00 sec)

 查看二进制日志内容：

mysql> show binlog events in 'master-bin.000001' from 24427;             ##master-bin.000001使用的是row格式，还未使用mixed的格式。
+-------------------+-------+----------------+-----------+-------------+--------------------------------------+
| Log_name          | Pos   | Event_type     | Server_id | End_log_pos | Info                                 |
+-------------------+-------+----------------+-----------+-------------+--------------------------------------+
| master-bin.000001 | 24427 | Anonymous_Gtid |        11 |       24492 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| master-bin.000001 | 24492 | Query          |        11 |       24564 | BEGIN                                |
| master-bin.000001 | 24564 | Table_map      |        11 |       24619 | table_id: 244 (mydb.mytb4)           |
| master-bin.000001 | 24619 | Write_rows     |        11 |       24730 | table_id: 244 flags: STMT_END_F      |
| master-bin.000001 | 24730 | Xid            |        11 |       24761 | COMMIT /* xid=266 */                 |
| master-bin.000001 | 24761 | Anonymous_Gtid |        11 |       24826 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| master-bin.000001 | 24826 | Query          |        11 |       24898 | BEGIN                                |
| master-bin.000001 | 24898 | Table_map      |        11 |       24953 | table_id: 244 (mydb.mytb4)           |
| master-bin.000001 | 24953 | Delete_rows    |        11 |       25008 | table_id: 244 flags: STMT_END_F      |
| master-bin.000001 | 25008 | Xid            |        11 |       25039 | COMMIT /* xid=280 */                 |
| master-bin.000001 | 25039 | Rotate         |        11 |       25087 | master-bin.000002;pos=4              |
+-------------------+-------+----------------+-----------+-------------+--------------------------------------+
11 rows in set (0.00 sec)

也可以是用mysqlbinlog工具进行查看：

[root@rs1 ~]# mysqlbinlog --start-position=24427 /usr/local/mysql/data/master-bin.000001
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170417 11:22:10 server id 11  end_log_pos 123 CRC32 0x65d2cfad     Start: binlog v 4, server v 5.7.17-log created 170417 11:22:10 at startup
ROLLBACK/*!*/;
BINLOG '
4jT0WA8LAAAAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADiNPRYEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
Aa3P0mU=
'/*!*/;
# at 24427
#170422  2:04:06 server id 11  end_log_pos 24492 CRC32 0x415b8d94     Anonymous_GTID    last_committed=86    sequence_number=87
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 24492
#170422  2:04:06 server id 11  end_log_pos 24564 CRC32 0xa586d324     Query    thread_id=11    exec_time=0    error_code=0
SET TIMESTAMP=1492797846/*!*/;
SET @@session.pseudo_thread_id=11/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 24564
#170422  2:04:06 server id 11  end_log_pos 24619 CRC32 0x660a6245     Table_map: `mydb`.`mytb4` mapped to number 244
# at 24619
#170422  2:04:06 server id 11  end_log_pos 24730 CRC32 0xc1a1bf49     Write_rows: table id 244 flags: STMT_END_F

BINLOG '
lkn6WBMLAAAANwAAACtgAAAAAPQAAAAAAAEABG15ZGIABW15dGI0AAQCDwH+BCwB9wEIRWIKZg==
lkn6WB4LAAAAbwAAAJpgAAAAAPQAAAAAAAEAAgAE//ABAAoAU29uZyBKaWFuZy0C8AIADQBaaGFu
ZyBTYW5mZW5nXgLwAwANAE1pZWp1ZSBTaGl0YWlNAfAEAAwATGluIENoYW95aW5nXQFJv6HB
'/*!*/;
# at 24730
#170422  2:04:06 server id 11  end_log_pos 24761 CRC32 0x3f44bb2e     Xid = 266
COMMIT/*!*/;
# at 24761
#170422  2:06:00 server id 11  end_log_pos 24826 CRC32 0xd301ea7f     Anonymous_GTID    last_committed=87    sequence_number=88
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 24826
#170422  2:06:00 server id 11  end_log_pos 24898 CRC32 0x765deb7a     Query    thread_id=12    exec_time=0    error_code=0
SET TIMESTAMP=1492797960/*!*/;
BEGIN
/*!*/;
# at 24898
#170422  2:06:00 server id 11  end_log_pos 24953 CRC32 0xf3513ec0     Table_map: `mydb`.`mytb4` mapped to number 244
# at 24953
#170422  2:06:00 server id 11  end_log_pos 25008 CRC32 0x1e59acd9     Delete_rows: table id 244 flags: STMT_END_F

BINLOG '
CEr6WBMLAAAANwAAAHlhAAAAAPQAAAAAAAEABG15ZGIABW15dGI0AAQCDwH+BCwB9wEIwD5R8w==
CEr6WCALAAAANwAAALBhAAAAAPQAAAAAAAEAAgAE//ADAA0ATWllanVlIFNoaXRhaU0B2axZHg==
'/*!*/;
# at 25008
#170422  2:06:00 server id 11  end_log_pos 25039 CRC32 0x822f3185     Xid = 280
COMMIT/*!*/;
# at 25039
#170422  3:14:30 server id 11  end_log_pos 25087 CRC32 0x7d427eb6     Rotate to master-bin.000002  pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

可以看出row模式不能看到原生的sql语句，这时候需要使用选项--base64-output=decode-rows 可以加上-v或者-vv增加日志的详细程度。

[root@rs1 ~]# mysqlbinlog --start-position=24427 --base64-output=decode-rows -vv /usr/local/mysql/data/master-bin.000001 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 24427
#170422  2:04:06 server id 11  end_log_pos 24492 CRC32 0x415b8d94     Anonymous_GTID    last_committed=86    sequence_number=87
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 24492
#170422  2:04:06 server id 11  end_log_pos 24564 CRC32 0xa586d324     Query    thread_id=11    exec_time=0    error_code=0
SET TIMESTAMP=1492797846/*!*/;
SET @@session.pseudo_thread_id=11/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 24564
#170422  2:04:06 server id 11  end_log_pos 24619 CRC32 0x660a6245     Table_map: `mydb`.`mytb4` mapped to number 244
# at 24619
#170422  2:04:06 server id 11  end_log_pos 24730 CRC32 0xc1a1bf49     Write_rows: table id 244 flags: STMT_END_F
### INSERT INTO `mydb`.`mytb4`
### SET
###   @1=1 /* SHORTINT meta=0 nullable=0 is_null=0 */
###   @2='Song Jiang' /* VARSTRING(300) meta=300 nullable=0 is_null=0 */
###   @3=45 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @4=2 /* ENUM(1 byte) meta=63233 nullable=1 is_null=0 */
### INSERT INTO `mydb`.`mytb4`
### SET
###   @1=2 /* SHORTINT meta=0 nullable=0 is_null=0 */
###   @2='Zhang Sanfeng' /* VARSTRING(300) meta=300 nullable=0 is_null=0 */
###   @3=94 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @4=2 /* ENUM(1 byte) meta=63233 nullable=1 is_null=0 */
### INSERT INTO `mydb`.`mytb4`
### SET
###   @1=3 /* SHORTINT meta=0 nullable=0 is_null=0 */
###   @2='Miejue Shitai' /* VARSTRING(300) meta=300 nullable=0 is_null=0 */
###   @3=77 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @4=1 /* ENUM(1 byte) meta=63233 nullable=1 is_null=0 */
### INSERT INTO `mydb`.`mytb4`
### SET
###   @1=4 /* SHORTINT meta=0 nullable=0 is_null=0 */
###   @2='Lin Chaoying' /* VARSTRING(300) meta=300 nullable=0 is_null=0 */
###   @3=93 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @4=1 /* ENUM(1 byte) meta=63233 nullable=1 is_null=0 */
# at 24730
#170422  2:04:06 server id 11  end_log_pos 24761 CRC32 0x3f44bb2e     Xid = 266
COMMIT/*!*/;
# at 24761
#170422  2:06:00 server id 11  end_log_pos 24826 CRC32 0xd301ea7f     Anonymous_GTID    last_committed=87    sequence_number=88
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 24826
#170422  2:06:00 server id 11  end_log_pos 24898 CRC32 0x765deb7a     Query    thread_id=12    exec_time=0    error_code=0
SET TIMESTAMP=1492797960/*!*/;
BEGIN
/*!*/;
# at 24898
#170422  2:06:00 server id 11  end_log_pos 24953 CRC32 0xf3513ec0     Table_map: `mydb`.`mytb4` mapped to number 244
# at 24953
#170422  2:06:00 server id 11  end_log_pos 25008 CRC32 0x1e59acd9     Delete_rows: table id 244 flags: STMT_END_F
### DELETE FROM `mydb`.`mytb4`
### WHERE
###   @1=3 /* SHORTINT meta=0 nullable=0 is_null=0 */
###   @2='Miejue Shitai' /* VARSTRING(300) meta=300 nullable=0 is_null=0 */
###   @3=77 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @4=1 /* ENUM(1 byte) meta=63233 nullable=1 is_null=0 */
# at 25008
#170422  2:06:00 server id 11  end_log_pos 25039 CRC32 0x822f3185     Xid = 280
COMMIT/*!*/;
# at 25039
#170422  3:14:30 server id 11  end_log_pos 25087 CRC32 0x7d427eb6     Rotate to master-bin.000002  pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

二进制日志可以使用重定向'>'做导出操作，在mysql备份和恢复中可以备份sql加上binlog进行恢复。

 

Log_name:此条log存在哪个文件中 

Pos:log在bin-log中的开始位置
Event_type:log的类型信息
Server_id:可以查看配置中的server_id,表示log是哪个服务器产生
End_log_pos：log在bin-log中的结束位置
Info:log的一些备注信息，可以直观的看出进行了什么操作

binlog还有其他一些附加选项参数:
“—max_binlog_size”设置 binlog的最大存储上限,当日志达到该上限时,MySQL 会重新创建一个日志开始继续记录。不过偶尔也有超出该设置的binlog产生,一般都是因为在即将达到上限时,产生了一个较大的事务,为了保证事务安全,MySQL不会将同一个事务分开记录到两个binlog中。
“—binlog-do-db=db_name”参数明确告诉 MySQL,需要对某个(db_name)数据库记录binlog,如果有了“—binlog-do-db=db_name”参数的显式指定,MySQL会忽略针对其他 数据库执行的query,而仅仅记录针对指定数据库执行的query。
“—binlog-ignore-db=db_name”与“—binlog-do-db=db_name”完全相反, 它显式指定忽略某个(db_name)数据库的binlog记录,当指定了这个参数之后,MySQL会记录指定数据库以外所有的数据库的 binlog。
“—binlog-ignore-db=db_name”与“—binlog-do-db=db_name”两个参数有一个共同的概念需要大家理解清楚,参数中的db_name不是指query语句更新的数据所在的数据库, 而是执行query的时候当前所处的数据库。不论更新哪个数据库的数据,MySQL仅仅比较当前连接所处的数据库(通过use db_name切换后所在的数据库)与参数设置的数据库名,而 不会分析query语句所更新数据所在的数据库。
mysql-bin.index 文件(binary log index)的功能是记录所有Binary Log的绝对路径,保证 MySQL各种线程能够顺利的根据它找到所有需要的Binary Log文件。

通用查询日志

mysql> show variables like '%general_log%';
+------------------+-------------------------------+
| Variable_name    | Value                         |
+------------------+-------------------------------+
| general_log      | OFF                           |
| general_log_file | /usr/local/mysql/data/rs1.log |
+------------------+-------------------------------+
2 rows in set (0.01 sec)

设置日志输出方式为文件（如果设置log_output=table的话，则日志结果会记录到名为gengera_log的表中，这表的默认引擎都是CSV）：

mysql> set @@global.log_output=file;
Query OK, 0 rows affected (0.00 sec)

设置general log的日志文件路径：

mysql> set @@global.general_log_file='/tmp/general.log';
Query OK, 0 rows affected (0.00 sec)

开启general log：

mysql> set @@global.general_log=on;
Query OK, 0 rows affected (0.00 sec)

过一段时间后，关闭general log：

mysql> set @@global.general_log=off;
Query OK, 0 rows affected (0.01 sec)

 

由于记录了所有的 query,包括所有的 select,体积比较大,开启后对性能也有较大的影响, 所以请大家慎用该功能。 一般只用于跟踪某些特殊的sql 性能问题才会短暂打开该功能。默认的查询日志文件名为 hostname.log。

慢查询日志

顾名思义,慢查询日志中记录的是执行时间较长的 query,也就是我们常说的 slow
query,通过设 —log-slow-queries[=file_name]来打开该功能并设置记录位置和文件名, 默认文件名为 hostname-slow.log,默认目录也是数据目录。
慢查询日志采用的是简单的文本格式, 可以通过各种文本编辑器查看其中的内容。中其 记录了语句执行的时刻,执行所消耗的时间,执行用户,连接主机等相关信息。MySQL 还提 供了专门用来分析满查询日志的工具程序mysqlslowdump, 用来帮助数据库管理人员解决可 能存在的性能问题。

Innodb的在线redo日志

Innodb 是一个事务安全的存储引擎, 其事务安全性主要就是通过在线redo 日志和记录
在表空间中的 undo 信息来保证的。redo 日志中记录了 Innodb 所做的所有物理变更和事务 信息, 通过redo 日志和 undo 信息, Innodb 保证了在任何情况下的事务安全性。Innodb 的redo 日志同样默认存放在数据目录下, 可以通过innodb_log_group_home_dir来更改设置日志的 存放位置,通过 innodb_log_files_in_group 设置日志的数量。

更新日志

更新日志是 MySQL 在较老的版本上使用的,其功能和 binlog 基本类似,只不过不是以
二进制格式来记录而是以简单的文本格式记录内容。自从 MySQL增加了binlog功能之后, 就很少使用更新日志了。从版本5.0 开始,MySQL 已经不再支持更新日志了。

总结

本篇文章整理了MySQL中的各种日志文件，每种日志文件都用其特定的用途，这些会在以后的文章中进行描述。