MySQL日志(转)

不管是哪个数据库产品，一定会有日志文件。在MariaDB/MySQL中，主要有5种日志文件：

错误日志(error log)：记录MySQL服务的启停时的正确和错误信息，还记录运行过程中的错误信息；
查询日志(general log): 记录建立的客户端连接和执行的语句；
二进制日志(bin log): 记录所有更改数据的语句，可用于数据复制；
慢查询日志(slow log): 记录所有执行时间超过long_query_time的查询或不使用索引的查询
中继日志(relay log): 主从复制时使用的日志

除了上述这5种日志，在需要的时候还会创建DDL日志。本文暂先讨论错误日志、一般查询日志、慢查询日志和二进制日志，中继日志和主从复制有关，请参看其他章节。

1. 日志刷新操作

以下操作会刷新日志文件。刷新日志文件时，会关闭旧的日志文件并重新打开日志文件。对于有些日志类型如binlog，刷新日志会滚动日志文件，而不仅仅是关闭并重新打开：

> FLUSH LOGS;

# mysqladmin -uroot -ptestAa@123 flush-logs
# mysqladmin -uroot -ptestAa@123 refresh

2. 错误日志

错误日志是最重要的日志之一，它记录了MariaDB/MySQL服务启动、停止时的正确和错误日志信息，还记录了mysqld实例运行过程中发生的错误信息。

可以使用--log-error=[file-name]来指定mysqld记录的错误日志文件，如果没有指定file-name，则默认的错误日志文件为datadir目录下的'hostname'.err，hostname表示当前的主机名。也可以在MySQL配置文件中的mysqld配置部分，使用log-error指定错误日志的路径，例如：

# cat /etc/my.cnf
[client]
default-character-set=utf8mb4
[mysqld]
show_compatibility_56=1
sql_mode=NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
character_set_server=utf8mb4
collation-server=utf8mb4_general_ci
lower_case_table_names=1
server-id=1
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid
log-bin=mysql-bin
symbolic-links=0
binlog_format=ROW
default_storage_engine=InnoDB
innodb_autoinc_lock_mode=2
innodb_locks_unsafe_for_binlog=1
innodb_buffer_pool_size        = 2048M
innodb_flush_method            = O_DIRECT
back_log = 600
max_connections = 1000
max_connect_errors = 6000
open_files_limit = 65535
table_open_cache = 128
max_allowed_packet = 64M
binlog_cache_size = 1M
max_heap_table_size = 8M
tmp_table_size = 64M
read_buffer_size = 8M
read_rnd_buffer_size = 32M
sort_buffer_size = 8M
join_buffer_size = 8M
thread_cache_size = 8
query_cache_size = 8M
query_cache_limit = 16M
key_buffer_size = 128M
ft_min_word_len = 4
transaction_isolation = REPEATABLE-READ
slow_query_log = 1
performance_schema = 0
explicit_defaults_for_timestamp
innodb_file_per_table = 1
innodb_open_files = 500
innodb_buffer_pool_size = 64M
innodb_write_io_threads = 4
innodb_read_io_threads = 4
innodb_thread_concurrency = 0
innodb_purge_threads = 1
innodb_flush_log_at_trx_commit = 2
innodb_log_buffer_size = 2M
innodb_log_file_size = 32M
innodb_log_files_in_group = 3
innodb_max_dirty_pages_pct = 90
innodb_lock_wait_timeout = 120 
bulk_insert_buffer_size = 8M
myisam_sort_buffer_size = 8M
myisam_max_sort_file_size = 10G
myisam_repair_threads = 1
interactive_timeout = 28800
wait_timeout = 28800
ignore-db-dir=lost+found
[mysqld_safe]
pid-file = /run/mysqld/mysqld.pid
syslog

如果不知道错误日志的位置，可以查看变量log_error:

mysql> show variables like 'log_error';
+---------------+---------------------+
| Variable_name | Value               |
+---------------+---------------------+
| log_error     | /var/log/mysqld.log |
+---------------+---------------------+
1 row in set (0.00 sec)

3. 一般日志查询

查询日志分为一般查询日志和慢查询日志，它们是通过查询是否超出变量long_query_time指定的时间值来判定的。在超时时间内完成的查询是一般查询，可以将其记录到一般查询日志中，但是建议关闭这种日志（默认是关闭的），超出时间的查询是慢查询，可以将其记录到慢查询日志中。

使用--general_log={0|1}来决定是否启用一般查询日志，使用--general_log_file=file_name来指定查询日志存放的路径。不给定路径时，默认的文件名以'hostname'.log命名。

和查询日志相关的变量有：

# 指定慢查询超时时长，超出此时长的属于慢查询，会记录到慢查询日志中(这里的单位是: 秒)
long_query_time = 10             

# 定义一般查询日志和慢查询日志的输出格式，不指定时默认为FILE
log_output = {TABLE | FILE | NONE}

上面log_ouput用于指定日志输出位置，其中TABLE表示日志记录到表中，FILE表示日志记录到文件中，NONE表示不记录日志。只要这里指定为NONE，即使开启了一般查询日志和慢查询日志，也都不会有任何记录。

和一般查询日志相关的变量有：

# 是否启用一般查询日志，为全局变量，必须在global上修改
general_log=off

# 在session级别控制是否启用一般查询日志，默认为off，即启用(注： 通常一个客户端连接代表一个session）
sql_log_off=off

# 默认是库文件路径下主机名加上.log
general_log_file=/mydata/data/hostname.log

在MySQL 5.6以前的版本还有一个log变量也是决定是否开启一般查询日志的。在5.6版本开始已经废弃了该选项。

默认没有开启一般查询日志，也不建议开启一般查询日志。此处我们演示打开该类型的日志，看看是如何记录一般查询日志的：

1）查看并修改一般查询日志相关变量

# 这里long_query_time为10s，我们不做修改
mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

# 此处默认为FILE输出格式，我们不做修改
mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.00 sec)

# 此处general_log默认为关闭，这里我们进行修改
mysql> show variables like 'general_log';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| general_log   | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

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


# 此处会话级别我们默认启用了一般查询日志，不做修改
mysql> show variables like 'sql_log_off';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| sql_log_off   | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

# 这里一般查询日志的输出文件名为compile.log，我们暂时不用修改
mysql> show variables like 'general_log_file';
+------------------+----------------------------+
| Variable_name    | Value                      |
+------------------+----------------------------+
| general_log_file | /var/lib/mysql/compile.log |
+------------------+----------------------------+
1 row in set (0.00 sec)

2) 执行如下语句

mysql> select host, user from mysql.user limit 2;
+------+---------+
| host | user    |
+------+---------+
| %    | canal   |
| %    | lykchat |
+------+---------+
2 rows in set (0.06 sec)

mysql> show table create mysql.user;
...

3) 查看一般查询日志的内容

# /var/lib/mysql/compile.log 
/usr/sbin/mysqld, Version: 5.7.17-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
2020-06-25T06:58:33.130102Z	 2766 Query	select host, user from mysql.user limit 2
2020-06-25T06:59:18.449367Z	 2766 Query	desc mysql.user
2020-06-25T07:00:31.424331Z	 2766 Query	show databases

由此可知，一般查询日志查询的不止是select语句，几乎所有的语句都会记录。

4) 关闭一般查询日志

这里我们测试完成后，记得关闭一般查询日志：

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

4. 慢查询日志

查询超出变量long_query_time指定时间值的为慢查询。但是查询获取锁（包括锁等待）的时间不计入查询时间内。

mysql慢查询日志是在查询执行完毕且已经完全释放锁之后才记录的，因此慢查询日志记录的顺序和执行的SQL查询语句的顺序可能会不一致（例如：语句1先执行，查询速度慢，语句2后执行，但查询速度快，则语句2先记录）。

注意： MySQL5.1之后就支持微妙级的慢查询超时时长，对于DBA来说，一个查询运行0.5秒和运行0.05秒是非常不同的，前者可能索引使用错误或者走了表扫描，后者可能索引使用正确。

另外，指定的慢查询超时时长表示的是超出这个时间才算是慢查询，等于这个时间的不会记录。和慢查询有关的变量：

# 指定慢查询超时时长(默认10秒)，超出此时长的属于慢查询
long_query_time=10

# 定义一般查询日志和慢查询日志的输出格式，默认为file
log_output={TABLE|FILE|NONE} 

# 是否启用慢查询日志，默认不启用
log_slow_queries={yes|no}    

# 也是是否启用慢查询日志，此变量和log_slow_queries修改一个另一个同时变化
slow_query_log={1|ON|0|OFF}  

#默认路径为库文件目录下主机名加上-slow.log
slow_query_log_file=/mydata/data/hostname-slow.log  

# 查询没有使用索引的时候是否也记入慢查询日志
log_queries_not_using_indexes=OFF

如下我们演示慢查询：

1）查看并修改一般查询日志相关变量

# 这里开启了
mysql> show variables like 'slow_query_log';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | ON    |
+----------------+-------+
1 row in set (0.00 sec)

# 如果没有开启，执行如下命令开启
mysql> set @@global.slow_query_log=on;

# 慢查询日志所存放的文件，作为演示，我们这里不做修改
mysql> show variables like 'slow_query_log_file';
+---------------------+---------------------------------+
| Variable_name       | Value                           |
+---------------------+---------------------------------+
| slow_query_log_file | /var/lib/mysql/compile-slow.log |
+---------------------+---------------------------------+
1 row in set (0.00 sec)

2) 执行一个慢查询

因为默认超时时长为10秒，所以这里我们执行一个10秒的查询：

# cat /var/lib/mysql/compile-slow.log
/usr/sbin/mysqld, Version: 5.7.17-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 2020-06-25T09:04:15.123406Z
# User@Host: root[root] @ localhost []  Id:  2766
# Query_time: 10.006276  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1593075855;
select sleep(10);

查看慢查询日志文件，这里看到虽然sleep了10秒，但是最后查询时间超出了6.276毫秒，因此这里也记录了该查询。

3）慢查询归类

随着时间的推移，慢查询日志文件中的记录可能会变得非常多，这对于分析查询来说是非常困难的。好在提供了一个专门归类慢查询日志的工具mysqldumpslow。其用法如下：

# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

Parse 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

我们在使用mysqldumpslow归类的时候，默认会将同文本但变量值不同的查询语句视为同一类，并使用N代替其中的数值变量，使用S代替其中的字符串变量，可以使用-a选项来禁用这种替换，例如：

# mysqldumpslow /var/lib/mysql/compile-slow.log
Reading mysql slow query log from xuexi-slow.log
Count: 1  Time=10.00s (10s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(N)

# mysqldumpslow -a /var/lib/mysql/compile-slow.log   
Reading mysql slow query log from xuexi-slow.log
Count: 1  Time=10.00s (10s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(10)

慢查询在SQL语句调优的时候非常有用，应该将它启用起来，且应该让慢查询阈值尽量小，例如1秒甚至低于1秒。就像一天执行上千次的1秒语句，和一天执行几次的20秒语句，显然更值得去优化这个1秒的语句。

5. 二进制日志(binlog)

5.1 二进制日志文件

二进制日志包含了引起或可能引起数据库改变(如delete语句但没有匹配行）的事件信息，但绝不会包括select和show这样的查询语句。语句以“事件”的形式保存，所以包含了时间、事件开始和结束位置等信息。

二进制日志是以事件形式记录的，不是事务日志(但可能是基于事务来记录二进制日志），不代表它只记录innodb日志，myisam表也一样有二进制日志。

对于事务表的操作，二进制日志只在事务提交的时候一次性写入（基于事务的innodb二进制日志），提交前的每个二进制日志记录都先cache，提交时写入。对于非事务表的操作，每次执行完语句就直接写入。

MariaDB/MySQL默认没有启用二进制日志，要启用二进制日志使用--log-bin=[on|off|file_name]选项指定，如果没有给定file_name，则默认为datadir下的’hostname-bin’，并在后面跟上一串数字表示日志序列号。如果给定的日志文件中包含了后缀(logname.suffix)，那么将忽略后缀部分。

# ls /var/lib/mysql/
mysql-bin.000001  mysql-bin.000002  mysql-bin.index

或者在配置文件中的[mysqld]部分设置log-bin也可以。例如：

# cat /etc/my.cnf
[mysqld]
server-id=1
datadir=/var/lib/mysql
log-bin=mysql-bin

注意：对于mysql 5.7，直接启动binlog可能会导致mysql服务启动失败，这时需要在配置文件中的mysqld为mysql实例分配server_id。

上面我们看到mysqld还创建了一个二进制日志索引文件(mysql-bin.index)，当二进制日志文件滚动的时候会向该文件中写入对应的信息。所以该文件包含所有使用的二进制日志文件的文件名。默认情况下该文件与二进制日志文件的文件名相同，扩展名为.index。如果要指定该文件的文件名，可以使用--log-bin-index[=file_name]选项。当mysqld在运行时，不应手动编辑该文件，免得mysqld变得混乱。

当重启mysql服务或刷新日志或者达到日志最大值时，将滚动二进制日志文件，滚动日志时只修改日志文件名的数字序列部分。

二进制日志文件的最大值通过变量 max_binlog_size 设置(默认值为1G)。但由于二进制日志可能是基于事务来记录的(如innodb表类型)，而事务是绝对不可能也不应该跨文件记录的，如果正好二进制日志文件达到了最大值但事务还没有提交则不会滚动日志，而是继续增大日志，所以 max_binlog_size 指定的值和实际的二进制日志大小不一定相等。

因为二进制日志文件增长迅速，但官方说明因此而损耗的性能小于1%，且二进制目的是为了恢复定点数据库和主从复制，所以出于安全和功能考虑，极不建议将二进制日志和datadir放在同一磁盘上。

5.2 查看二进制日志

MySQL中查看二进制日志的方法主要有如下：

使用mysqlbinlog工具
使用show显示对应的信息

SHOW {BINARY | MASTER} LOGS                     # 查看使用了哪些日志文件
SHOW BINLOG EVENTS [IN 'log_name'] [FROM pos]   # 查看日志中进行了哪些操作
SHOW MASTER STATUS                              # 显式主服务器中的二进制日志信息

5.2.1 mysqlbinlog

二进制日志可以使用mysqlbinlog命令查看：

# mysqlbinlog --no-defaults --help
Usage: mysqlbinlog [options] log-files

注：这里添加了--no-defaults选项，以阻止如下错误：

mysqlbinlog: [ERROR] unknown variable ‘default-character-set=utf8mb4’

以下是常用的几个选项：

-d, --database=name : 只查看指定数据库的日志操作

-o, --offset=# : 忽略掉日志中的前n个操作命令

-r, --result-file=name : 将输出的日志信息输出到指定的文件中，使用重定向也一样可以

-s, --short-form : 显示简单格式的日志，只记录一些普通的语句，会省略掉一些额外的信息如位置信息和时间信息以及基于行的日志。
                   可以用来调试，生产环境千万不可使用

--set-charset=char_name : 在输出日志信息到文件中时，在文件第一行加上set names char_name

--start-datetime, --stop-datetime=name: 指定输出开始时间和结束时间内的所有日志信息。例如--start-datetime='2004-12-25 11:25:56'

--start-position=#, --stop-position=# : 指定输出开始位置和结束位置内的所有日志信息

-v, -vv : 显示更详细信息，基于row的日志默认不会显示出来，此时使用-v或-vv可以查看

在进行测试之前，先对日志进行一次刷新，以方便解释二进制日志的信息（实际生产环境不要这样操作，这里只是为了方便学习，先进行日志刷新）：

//shell命令行执行
# mysqladmin -uroot -p refresh

假设现在的日志文件是mysql-bin.000001，里面暂时只有一些初始信息，没有记录任何操作过的记录。

下面是每个二进制日志文件的初始信息。可以看到记录了时间和位置信息(at 4):

# mysqlbinlog mysql-bin.000001 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170329  2:18:10 server id 1  end_log_pos 120 CRC32 0x40f62523  Start: binlog v 4, server v 5.6.35-log created 170329  2:18:10 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
4qjaWA8BAAAAdAAAAHgAAAABAAQANS42LjM1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADiqNpYEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAASMl
9kA=
'/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

现在数据库中执行下面的操作：

use test;
create table student(studentid int not null primary key,name varchar(30) not null,gender enum('female','mail'));
alter table student change gender gender enum('female','male');
insert into student values(1,'malongshuai','male'),(2,'gaoxiaofang','female');

再查看二进制日志信息：

# mysqlbinlog mysql-bin.000001 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170329  2:18:10 server id 1  end_log_pos 120 CRC32 0x40f62523  Start: binlog v 4, server v 5.6.35-log created 170329  2:18:10 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
4qjaWA8BAAAAdAAAAHgAAAABAAQANS42LjM1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADiqNpYEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAASMl
9kA=
'/*!*/;
# at 120
#170329  5:20:00 server id 1  end_log_pos 305 CRC32 0xbac43912  Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1490736000/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table student(studentid int not null primary key,name varchar(30) not null,gender enum('female','mail'))
/*!*/;
# at 305
#170329  5:21:21 server id 1  end_log_pos 441 CRC32 0xde67f702  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736081/*!*/;
alter table student change gender gender enum('female','male')
/*!*/;
# at 441
#170329  5:21:33 server id 1  end_log_pos 520 CRC32 0x05a9c5a1  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736093/*!*/;
BEGIN
/*!*/;
# at 520
#170329  5:21:33 server id 1  end_log_pos 671 CRC32 0xad9e7dc8  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736093/*!*/;
insert into student values(1,'malongshuai','male'),(2,'gaoxiaofang','female')
/*!*/;
# at 671
#170329  5:21:33 server id 1  end_log_pos 702 CRC32 0xb69b0f7d  Xid = 32
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

将上述信息整理为下图：其中timestamp记录的是从1970-01-01到现在的总秒数时间戳，可以使用date -d '@1490736093'转换。

db-mysql-binlog

位置0-120记录的是二进制日志的一些固定信息；
位置120-305记录的是use和create table语句，语句的记录时间为5:20:00。但注意，这里的use不是执行的use语句，而是MySQL发现要操作的数据库为test，而自动进行的操作并记录下来。人为的use语句是不会记录的。
位置305-441记录的是alter table语句，语句的记录时间为5:20:21
位置441-702记录的是insert操作，因为该操作是DML语句，因此记录了事务的开始BEGIN和提交COMMIT
- begin的起止位置为441-520;
- insert into语句的起止位置为520-671，记录的时间和自动开启事务的begin时间是一样的；
- commit的起止位置为671-702

可以使用-r命令将日志文件导入到指定文件中，使用重定向也可以实现同样的结果。并使用-s查看简化的日志文件：

# mysqlbinlog mysql-bin.000001 -r /tmp/binlog.000001

# mysqlbinlog mysql-bin.000001 -s>/tmp/binlog.sample

比较这两个文件，看看简化的日志文件简化了哪些东西：

db-mysql-slog

从上图中可以看出，使用-s后，少了基于行的日志信息，也少了记录的位置和时间信息。

使用-o可以忽略前N个条目，例如上面的操作涉及了6个操作，忽略掉3个后的日志显示如下：可以看到直接从位置441开始显示了。

# mysqlbinlog mysql-bin.000001 -o 3
...前面固定部分省略...

'/*!*/;
# at 441
#170329  5:21:33 server id 1  end_log_pos 520 CRC32 0x05a9c5a1  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736093/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 520
#170329  5:21:33 server id 1  end_log_pos 671 CRC32 0xad9e7dc8  Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1490736093/*!*/;
insert into student values(1,'malongshuai','male'),(2,'gaoxiaofang','female')
/*!*/;
# at 671
#170329  5:21:33 server id 1  end_log_pos 702 CRC32 0xb69b0f7d  Xid = 32
COMMIT/*!*/;
DELIMITER ;

...后面固定部分省略...

使用-d可以只显示指定数据库相关的操作。例如先切换到其他数据库进行一番操作，然后再使用-d查看日志:

mysql> use mysql;
mysql> create table mytest(id int);

# mysqlbinlog mysql-bin.000001 -d mysql
...前固定部分省略...'/*!*/;
# at 120
# at 305
# at 441
#170329  5:21:33 server id 1  end_log_pos 520 CRC32 0x05a9c5a1  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736093/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 520
# at 671
#170329  5:21:33 server id 1  end_log_pos 702 CRC32 0xb69b0f7d  Xid = 32
COMMIT/*!*/;
# at 702
#170329  6:27:12 server id 1  end_log_pos 805 CRC32 0x491529ff  Query   thread_id=1     exec_time=0     error_code=0
use `mysql`/*!*/;
SET TIMESTAMP=1490740032/*!*/;
create table mytest(id int)
/*!*/;
DELIMITER ;
...后面固定部分省略...

可以看到，除了指定的mysql数据库的信息输出了，还非常简化的输出了其他数据库的信息。

mysqlbinlog最有用的两个选项就是指定时间和位置来输出日志。指定时间时，将输出指定时间范围内的日志。指定的时间可以不和日志中记录的日志相同（比如日志中有2017-03-28 00:00.01，但是没有2017-03-28 00:00.02，这时我们也可以指定2017-03-28 00:00.02这个不存在的时间点）：

# mysqlbinlog mysql-bin.000001 --start-datetime='2017-03-28 00:00:01' --stop-datetime='2017-03-29 05:21:23'
...前面固定部分省略...
'/*!*/;
# at 120
#170329  5:20:00 server id 1  end_log_pos 305 CRC32 0xbac43912  Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1490736000/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table student(studentid int not null primary key,name varchar(30) not null,gender enum('female','mail'))
/*!*/;
# at 305
#170329  5:21:21 server id 1  end_log_pos 441 CRC32 0xde67f702  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736081/*!*/;
alter table student change gender gender enum('female','male')
/*!*/;
DELIMITER ;
...后面固定部分省略...

同理，指定位置也一样，但是指定位置时有个要求是如果指定起始位置，则必须指定日志文件中明确的起始位置。例如，日志文件中有位置120、305、441，那么我们可以指定起始和结束位置为120、500，但是不能指定起止位置为150、500，因为日志文件中不存在150这个位置：

# mysqlbinlog mysql-bin.000001 --start-position=150 --stop-position=441
...前面固定部分省略...
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 4202496, event_type: 0
...后面固定部分省略... 

[root@xuexi data]# mysqlbinlog mysql-bin.000001 --start-position=305 --stop-position=500
...前面固定部分省略... 
'/*!*/;
# at 305
#170329  5:21:21 server id 1  end_log_pos 441 CRC32 0xde67f702  Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1490736081/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
alter table student change gender gender enum('female','male')
/*!*/;
# at 441
#170329  5:21:33 server id 1  end_log_pos 520 CRC32 0x05a9c5a1  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490736093/*!*/;
BEGIN
/*!*/;
DELIMITER ;
...后面固定部分省略...

5.2.2 show binary logs

该语句用于查看当前使用了哪些二进制日志文件。可以通过查看二进制的index文件来查看当前正在使用哪些二进制日志：

# cat mysql-bin.index 
./mysql-bin.000003
./mysql-bin.000004
./mysql-bin.000005
./mysql-bin.000006

也可以在mysql环境中使用show {binary|master} logs来查看。binary和master是同义词。

mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000003 |       167 |
| mysql-bin.000004 |       785 |
| mysql-bin.000005 |      1153 |
| mysql-bin.000006 |       602 |
+------------------+-----------

5.2.3 show binlog events

该语句用于查看日志中进行了哪些操作：

mysql> show binlog events in 'mysql-bin.000005';

db-mysql-tlog

可以指定起始位置。同样，起始位置必须指定正确，不能指定不存在的位置：

mysql> show binlog events in 'mysql-bin.000005' from 961;
+------------------+------+------------+-----------+-------------+--------------------------------+
| Log_name         | Pos  | Event_type | Server_id | End_log_pos | Info                           |
+------------------+------+------------+-----------+-------------+--------------------------------+
| mysql-bin.000005 |  961 | Table_map  |         1 |        1019 | table_id: 98 (test.student)    |
| mysql-bin.000005 | 1019 | Write_rows |         1 |        1075 | table_id: 98 flags: STMT_END_F |
| mysql-bin.000005 | 1075 | Xid        |         1 |        1106 | COMMIT /* xid=129 */           |
| mysql-bin.000005 | 1106 | Rotate     |         1 |        1153 | mysql-bin.000006;pos=4         |
+------------------+------+------------+-----------+-------------+--------------------------------+

5.2.4 show master status

该语句用于显示主服务器中的二进制日志信息。如果是主从结构，它只会显示主从结构中主服务器的二进制日志信息:

mysql> show master status;    
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000006 |      602 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+

可以查看到当前正在使用的日志及下一事件记录的开始位置，还能查看到哪些数据库需要记录二进制日志，哪些数据库不记录二进制日志。

5.3 删除二进制日志

删除二进制日志有几种方法，不管哪种方法，都会将删除后的信息同步到二进制index文件中。

1） reset master将会删除所有日志，并让日志文件重新从000001开始

mysql> reset master;

2) purge日志

用法如下：

PURGE { BINARY | MASTER } LOGS { TO 'log_name' | BEFORE datetime_expr }

例如：

mysql> purge master logs to "mysql-bin.000006";
mysql> purge binary logs to "mysql-bin.000006";

上面的命令将会删除000006之前的日志文件。（binary和master是同义词）。

如下命令：

mysql> purge master logs before '2017-03-29 07:36:40';

mysql> show warnings;
+---------+------+---------------------------------------------------------------------------+
| Level   | Code | Message                                                                   |
+---------+------+---------------------------------------------------------------------------+
| Warning | 1868 | file ./mysql-bin.000003 was not purged because it is the active log file. |
+---------+------+---------------------------------------------------------------------------+

则会清除2017-03-29 07:36:40之前的日志。

5.4 二进制日志的记录格式

在MySQL5.1之前，MySQL只有一种基于语句statement形式的日志记录格式。即将所有的相关操作记录为SQL语句形式。但是这样的记录方式对某些特殊信息无法同步记录，例如uuid，now()等这样动态变化的值。

从MySQL5.1 MySQL支持statement、row、mixed三种形式的记录方式。row形式是基于行来记录，也就是将相关行的每一列的值都在日志中保存下来，这样的结果会导致日志文件变得非常大，但是保证了动态值的确定性。还有一种mixed形式，表示如何记录日志由MySQL自己来决定。

日志的记录格式由变量binlog_format来指定。其值有： row，statement，mixed。innodb引擎的创始人之一在博客上推荐使用row格式。

下面将记录格式改为row：

mysql> alter table student add birthday datetime default  now();
mysql> flush logs;
mysql> set binlog_format='row';
mysql> insert into student values(7,'xiaowoniu','female',now());

查看产生的日志：

[root@xuexi data]# mysqlbinlog mysql-bin.000005
...前面固定部分省略...
'/*!*/;
# at 120
#170329  8:06:24 server id 1  end_log_pos 200 CRC32 0x0ac02649  Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1490745984/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 200
#170329  8:06:24 server id 1  end_log_pos 258 CRC32 0xb8cdfd09  Table_map: `test`.`student` mapped to number 94
# at 258
#170329  8:06:24 server id 1  end_log_pos 314 CRC32 0x8ce6f72c  Write_rows: table id 94 flags: STMT_END_F

BINLOG '
gPraWBMBAAAAOgAAAAIBAAAAAF4AAAAAAAEABHRlc3QAB3N0dWRlbnQABAMP/hIFHgD3AQAMCf3N
uA==
gPraWB4BAAAAOAAAADoBAAAAAF4AAAAAAAEAAgAE//AHAAAACXhpYW93b25pdQGZnDqBmCz35ow=
'/*!*/;
# at 314
#170329  8:06:24 server id 1  end_log_pos 345 CRC32 0x7a48c057  Xid = 114
COMMIT/*!*/;
DELIMITER ;
...后面固定部分省略...

发现一堆看不懂的东西，使用-vv可将这些显示出来。可以看出，结果中记录的非常详细，这也是为什么基于row记录日志会导致日志文件急速变大：

[root@xuexi data]# mysqlbinlog mysql-bin.000005 -vv
...前面省略...
BINLOG '
gPraWBMBAAAAOgAAAAIBAAAAAF4AAAAAAAEABHRlc3QAB3N0dWRlbnQABAMP/hIFHgD3AQAMCf3N
uA==
gPraWB4BAAAAOAAAADoBAAAAAF4AAAAAAAEAAgAE//AHAAAACXhpYW93b25pdQGZnDqBmCz35ow=
'/*!*/;
### INSERT INTO `test`.`student`
### SET
###   @1=7 /* INT meta=0 nullable=0 is_null=0 */
###   @2='xiaowoniu' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
###   @3=1 /* ENUM(1 byte) meta=63233 nullable=1 is_null=0 */
###   @4='2017-03-29 08:06:24' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
# at 314
...后面省略...

还有一种mixed模式。这种模式下默认会采用statement的方式记录，只有以下几种情况会采用row的形式来记录日志：

表的存储引擎为NDB，这时对表的DML操作都会以row的格式记录；
使用了uuid()、user()、current_user()、found_rows()、row_count()等不确定函数。但测试发现now()函数仍会以statement格式记录，而sysdate()函数会以row格式记录；
使用了insert delay语句；
使用了临时表

[参看]:

Ivanzz

发上等愿，结中等缘，享下等福；择高处立，寻平处住，向宽处行