前言

官方手冊:https://dev.mysql.com/doc/refman/5.7/en/server-logs.html

不管是哪個數(shù)據(jù)庫產(chǎn)品，一定會有日志文件。在MariaDB/MySQL中，主要有5種日志文件：

1.錯誤日志(error log)：記錄mysql服務(wù)的啟停時正確和錯誤的信息，還記錄啟動、停止、運行過程中的錯誤信息。

2.查詢?nèi)罩?general log)：記錄建立的客戶端連接和執(zhí)行的語句。

3.二進(jìn)制日志(bin log)：記錄所有更改數(shù)據(jù)的語句，可用于數(shù)據(jù)復(fù)制。

4.慢查詢?nèi)罩?slow log)：記錄所有執(zhí)行時間超過long_query_time的所有查詢或不使用索引的查詢。

5.中繼日志(relay log)：主從復(fù)制時使用的日志。

除了這5種日志，在需要的時候還會創(chuàng)建DDL日志。本文暫先討論錯誤日志、一般查詢?nèi)罩?、慢查詢?nèi)罩竞投M(jìn)制日志，中繼日志和主從復(fù)制有關(guān)，將在復(fù)制的章節(jié)中介紹。下一篇文章將介紹innodb事務(wù)日志，見：MySQL的事務(wù)日志。

1.日志刷新操作

以下操作會刷新日志文件，刷新日志文件時會關(guān)閉舊的日志文件并重新打開日志文件。對于有些日志類型，如二進(jìn)制日志，刷新日志會滾動日志文件，而不僅僅是關(guān)閉并重新打開。

mysql> FLUSH LOGS;
shell> mysqladmin flush-logs
shell> mysqladmin refresh

2.錯誤日志

錯誤日志是最重要的日志之一，它記錄了MariaDB/MySQL服務(wù)啟動和停止正確和錯誤的信息，還記錄了mysqld實例運行過程中發(fā)生的錯誤事件信息。

可以使用"--log-error=[file_name]"來指定mysqld記錄的錯誤日志文件，如果沒有指定file_name，則默認(rèn)的錯誤日志文件為datadir目錄下的`hostname`.err，hostname表示當(dāng)前的主機(jī)名。

也可以在MariaDB/MySQL配置文件中的mysqld配置部分，使用log-error指定錯誤日志的路徑。

如果不知道錯誤日志的位置，可以查看變量log_error來查看。

mysql> show variables like 'log_error';
+---------------+----------------------------------------+
| Variable_name | Value                                  |
+---------------+----------------------------------------+
| log_error     | /var/lib/mysql/node1.longshuai.com.err |
+---------------+----------------------------------------+

在MySQL 5.5.7之前，刷新日志操作(如flush logs)會備份舊的錯誤日志(以_old結(jié)尾)，并創(chuàng)建一個新的錯誤日志文件并打開，在MySQL 5.5.7之后，執(zhí)行刷新日志的操作時，錯誤日志會關(guān)閉并重新打開，如果錯誤日志不存在，則會先創(chuàng)建。

在MariaDB/MySQL正在運行狀態(tài)下刪除錯誤日志后，不會自動創(chuàng)建錯誤日志，只有在刷新日志的時候才會創(chuàng)建一個新的錯誤日志文件。

以下是MySQL 5.6.35啟動的日志信息。

2017-03-29 01:15:14 2362 [Note] Plugin 'FEDERATED' is disabled.
2017-03-29 01:15:14 2362 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-03-29 01:15:14 2362 [Note] InnoDB: The InnoDB memory heap is disabled
2017-03-29 01:15:14 2362 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-03-29 01:15:14 2362 [Note] InnoDB: Memory barrier is not used
2017-03-29 01:15:14 2362 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-03-29 01:15:14 2362 [Note] InnoDB: Using Linux native AIO
2017-03-29 01:15:14 2362 [Note] InnoDB: Using CPU crc32 instructions
2017-03-29 01:15:14 2362 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2017-03-29 01:15:14 2362 [Note] InnoDB: Completed initialization of buffer pool
2017-03-29 01:15:14 2362 [Note] InnoDB: Highest supported file format is Barracuda.
2017-03-29 01:15:14 2362 [Note] InnoDB: 128 rollback segment(s) are active.
2017-03-29 01:15:14 2362 [Note] InnoDB: Waiting for purge to start
2017-03-29 01:15:14 2362 [Note] InnoDB: 5.6.35 started; log sequence number 3911610
2017-03-29 01:15:14 2362 [Note] Server hostname (bind-address): '*'; port: 3306
2017-03-29 01:15:14 2362 [Note] IPv6 is available.
2017-03-29 01:15:14 2362 [Note]   - '::' resolves to '::';
2017-03-29 01:15:14 2362 [Note] Server socket created on IP: '::'.
2017-03-29 01:15:14 2362 [Warning] 'proxies_priv' entry '@ root@xuexi.longshuai.com' ignored in --skip-name-resolve mode.
2017-03-29 01:15:14 2362 [Note] Event Scheduler: Loaded 0 events
2017-03-29 01:15:14 2362 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.35'  socket: '/mydata/data/mysql.sock'  port: 3306  MySQL Community Server (GPL)

3.一般查詢?nèi)罩?/h2>

查詢?nèi)罩痉譃橐话悴樵內(nèi)罩竞吐樵內(nèi)罩?，它們是通過查詢是否超出變量long_query_time指定時間的值來判定的。在超時時間內(nèi)完成的查詢是一般查詢，可以將其記錄到一般查詢?nèi)罩局?，但是建議關(guān)閉這種日志（默認(rèn)是關(guān)閉的），超出時間的查詢是慢查詢，可以將其記錄到慢查詢?nèi)罩局小?/p>

使用"--general_log={0|1}"來決定是否啟用一般查詢?nèi)罩?，使?quot;--general_log_file=file_name"來指定查詢?nèi)罩镜穆窂?。不給定路徑時默認(rèn)的文件名以`hostname`.log命名。

和查詢?nèi)罩居嘘P(guān)的變量有：

long_query_time = 10 # 指定慢查詢超時時長，超出此時長的屬于慢查詢，會記錄到慢查詢?nèi)罩局?
log_output={TABLE|FILE|NONE}  # 定義一般查詢?nèi)罩竞吐樵內(nèi)罩镜妮敵龈袷?，不指定時默認(rèn)為file

TABLE表示記錄日志到表中，F(xiàn)ILE表示記錄日志到文件中，NONE表示不記錄日志。只要這里指定為NONE，即使開啟了一般查詢?nèi)罩竞吐樵內(nèi)罩荆捕疾粫腥魏斡涗洝?/p>

和一般查詢?nèi)罩鞠嚓P(guān)的變量有：

general_log=off # 是否啟用一般查詢?nèi)罩?，為全局變量，必須在global上修改。
sql_log_off=off # 在session級別控制是否啟用一般查詢?nèi)罩荆J(rèn)為off，即啟用
general_log_file=/mydata/data/hostname.log  # 默認(rèn)是庫文件路徑下主機(jī)名加上.log

在MySQL 5.6以前的版本還有一個"log"變量也是決定是否開啟一般查詢?nèi)罩镜?。?.6版本開始已經(jīng)廢棄了該選項。

默認(rèn)沒有開啟一般查詢?nèi)罩荆膊唤ㄗh開啟一般查詢?nèi)罩?。此處打開該類型的日志，看看是如何記錄一般查詢?nèi)罩镜摹?/p>

首先開啟一般查詢?nèi)罩尽?/p>

mysql> set @@global.general_log=1;

[root@xuexi data]# ll *.log
-rw-rw---- 1 mysql mysql 5423 Mar 20 16:29 mysqld.log
-rw-rw---- 1 mysql mysql  262 Mar 29 09:31 xuexi.log

執(zhí)行幾個語句。

mysql> select host,user from mysql.user;
mysql> show variables like "%error%";
mysql> insert into ttt values(233);
mysql> create table tt(id int);
mysql> set @a:=3;

查看一般查詢?nèi)罩镜膬?nèi)容。

[root@xuexi data]# cat xuexi.log 
/usr/local/mysql/bin/mysqld, Version: 5.6.35-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /mydata/data/mysql.sock
Time                Id Command    Argument
180421 20:04:41     13 Query      select user,host from mysql.user
180421 20:06:06     13 Query      show variables like "%error%"
180421 20:07:28     13 Query      insert into ttt values(233)
180421 20:11:47     13 Query      create table tt(id int)
180421 20:12:29     13 Query      set @a:=3

由此可知，一般查詢?nèi)罩静樵兊牟恢故莝elect語句，幾乎所有的語句都會記錄。

4.慢查詢?nèi)罩?/h2>

查詢超出變量long_query_time指定時間值的為慢查詢。但是查詢獲取鎖(包括鎖等待)的時間不計入查詢時間內(nèi)。

mysql記錄慢查詢?nèi)罩臼窃诓樵儓?zhí)行完畢且已經(jīng)完全釋放鎖之后才記錄的，因此慢查詢?nèi)罩居涗浀捻樞蚝蛨?zhí)行的SQL查詢語句順序可能會不一致(例如語句1先執(zhí)行，查詢速度慢，語句2后執(zhí)行，但查詢速度快，則語句2先記錄)。

注意，MySQL 5.1之后就支持微秒級的慢查詢超時時長，對于DBA來說，一個查詢運行0.5秒和運行0.05秒是非常不同的，前者可能索引使用錯誤或者走了表掃描，后者可能索引使用正確。

另外，指定的慢查詢超時時長表示的是超出這個時間的才算是慢查詢，等于這個時間的不會記錄。

和慢查詢有關(guān)的變量：

long_query_time=10 # 指定慢查詢超時時長(默認(rèn)10秒)，超出此時長的屬于慢查詢
log_output={TABLE|FILE|NONE} # 定義一般查詢?nèi)罩竞吐樵內(nèi)罩镜妮敵龈袷剑J(rèn)為file
log_slow_queries={yes|no}    # 是否啟用慢查詢?nèi)罩?，默認(rèn)不啟用
slow_query_log={1|ON|0|OFF}  # 也是是否啟用慢查詢?nèi)罩?，此變量和log_slow_queries修改一個另一個同時變化
slow_query_log_file=/mydata/data/hostname-slow.log  #默認(rèn)路徑為庫文件目錄下主機(jī)名加上-slow.log
log_queries_not_using_indexes=OFF # 查詢沒有使用索引的時候是否也記入慢查詢?nèi)罩?/pre>

現(xiàn)在啟用慢查詢?nèi)罩尽?/p>

mysql> set @@global.slow_query_log=on;

因為默認(rèn)超時時長為10秒，所以進(jìn)行一個10秒的查詢。

mysql> select sleep(10);

查看慢查詢?nèi)罩疚募?。這里看到雖然sleep了10秒，但是最后查詢時間超出了847微秒，因此這里也記錄了該查詢。

[root@xuexi data]# cat xuexi-slow.log 
/usr/local/mysql/bin/mysqld, Version: 5.6.35-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /mydata/data/mysql.sock
Time                 Id Command    Argument
# Time: 170329  9:55:58
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 10.000847  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use test;
SET timestamp=1490752558;
select sleep(10);

隨著時間的推移，慢查詢?nèi)罩疚募械挠涗浛赡軙兊梅浅６?，這對于分析查詢來說是非常困難的。好在提供了一個專門歸類慢查詢?nèi)罩镜墓ぞ適ysqldumpslow。

[root@xuexi data]# mysqldumpslow --help
  -d           debug 
  -v           verbose：顯示詳細(xì)信息
  -t NUM       just show the top n queries：僅顯示前n條查詢
  -a           don't abstract all numbers to N and strings to 'S'：歸類時不要使用N替換數(shù)字，S替換字符串
  -g PATTERN   grep: only consider stmts that include this string：通過grep來篩選select語句。

該工具歸類的時候，默認(rèn)會將同文本但變量值不同的查詢語句視為同一類，并使用N代替其中的數(shù)值變量，使用S代替其中的字符串變量?？梢允褂?a來禁用這種替換。如：

[root@xuexi data]# mysqldumpslow xuexi-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)

[root@xuexi data]#  mysqldumpslow -a xuexi-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)

顯然，這里歸類后的結(jié)果只是精確到0.01秒的，如果想要顯示及其精確的秒數(shù)，則使用-d選項啟用調(diào)試功能。

[root@xuexi data]#  mysqldumpslow -d xuexi-slow.log   
Reading mysql slow query log from xuexi-slow.log
[[/usr/local/mysql/bin/mysqld, Version: 5.6.35-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /mydata/data/mysql.sock
Time                 Id Command    Argument
# Time: 170329  9:55:58
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 10.000847  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use test;
SET timestamp=1490752558;
select sleep(10);
]]
<<>>
<<# Time: 170329  9:55:58
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 10.000847  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use test;
SET timestamp=1490752558;
select sleep(10);
>> at /usr/local/mysql/bin/mysqldumpslow line 97, <> chunk 1.
[[# Time: 170329  9:55:58
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 10.000847  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use test;
SET timestamp=1490752558;
select sleep(10);
]]
{{  select sleep(N)}}

Count: 1  Time=10.00s (10s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(N)

慢查詢在SQL語句調(diào)優(yōu)的時候非常有用，應(yīng)該將它啟用起來，且應(yīng)該讓慢查詢閾值盡量小，例如1秒甚至低于1秒。就像一天執(zhí)行上千次的1秒語句，和一天執(zhí)行幾次的20秒語句，顯然更值得去優(yōu)化這個1秒的語句。

5.二進(jìn)制日志

5.1 二進(jìn)制日志文件

二進(jìn)制日志包含了引起或可能引起數(shù)據(jù)庫改變(如delete語句但沒有匹配行)的事件信息，但絕不會包括select和show這樣的查詢語句。語句以"事件"的形式保存，所以包含了時間、事件開始和結(jié)束位置等信息。

二進(jìn)制日志是以事件形式記錄的，不是事務(wù)日志(但可能是基于事務(wù)來記錄二進(jìn)制日志)，不代表它只記錄innodb日志，myisam表也一樣有二進(jìn)制日志。

對于事務(wù)表的操作，二進(jìn)制日志只在事務(wù)提交的時候一次性寫入(基于事務(wù)的innodb二進(jìn)制日志)，提交前的每個二進(jìn)制日志記錄都先cache，提交時寫入。

所以，對于事務(wù)表來說，一個事務(wù)中可能包含多條二進(jìn)制日志事件，它們會在提交時一次性寫入。而對于非事務(wù)表的操作，每次執(zhí)行完語句就直接寫入。

MariaDB/MySQL默認(rèn)沒有啟動二進(jìn)制日志，要啟用二進(jìn)制日志使用--log-bin=[on|off|file_name]選項指定，如果沒有給定file_name，則默認(rèn)為datadir下的主機(jī)名加"-bin"，并在后面跟上一串?dāng)?shù)字表示日志序列號，如果給定的日志文件中包含了后綴(logname.suffix)將忽略后綴部分。

或者在配置文件中的[mysqld]部分設(shè)置log-bin也可以。注意：對于mysql 5.7，直接啟動binlog可能會導(dǎo)致mysql服務(wù)啟動失敗，這時需要在配置文件中的mysqld為mysql實例分配server_id。

[mysqld]
# server_id=1234
log-bin=[on|filename]

mysqld還創(chuàng)建一個二進(jìn)制日志索引文件，當(dāng)二進(jìn)制日志文件滾動的時候會向該文件中寫入對應(yīng)的信息。所以該文件包含所有使用的二進(jìn)制日志文件的文件名。默認(rèn)情況下該文件與二進(jìn)制日志文件的文件名相同，擴(kuò)展名為'.index'。要指定該文件的文件名使用--log-bin-index[=file_name]選項。當(dāng)mysqld在運行時不應(yīng)手動編輯該文件，免得mysqld變得混亂。

當(dāng)重啟mysql服務(wù)或刷新日志或者達(dá)到日志最大值時，將滾動二進(jìn)制日志文件，滾動日志時只修改日志文件名的數(shù)字序列部分。

二進(jìn)制日志文件的最大值通過變量max_binlog_size設(shè)置(默認(rèn)值為1G)。但由于二進(jìn)制日志可能是基于事務(wù)來記錄的(如innodb表類型)，而事務(wù)是絕對不可能也不應(yīng)該跨文件記錄的，如果正好二進(jìn)制日志文件達(dá)到了最大值但事務(wù)還沒有提交則不會滾動日志，而是繼續(xù)增大日志，所以max_binlog_size指定的值和實際的二進(jìn)制日志大小不一定相等。

因為二進(jìn)制日志文件增長迅速，但官方說明因此而損耗的性能小于1%，且二進(jìn)制目的是為了恢復(fù)定點數(shù)據(jù)庫和主從復(fù)制，所以出于安全和功能考慮，極不建議將二進(jìn)制日志和datadir放在同一磁盤上。

5.2 查看二進(jìn)制日志

MySQL中查看二進(jìn)制日志的方法主要有幾種。

1.使用mysqlbinlog工具。

2.使用show顯示對應(yīng)的信息。

SHOW {BINARY | MASTER} LOGS      # 查看使用了哪些日志文件
SHOW BINLOG EVENTS [IN 'log_name'] [FROM pos]   # 查看日志中進(jìn)行了哪些操作
SHOW MASTER STATUS         # 顯式主服務(wù)器中的二進(jìn)制日志信息

5.2.1 mysqlbinlog

二進(jìn)制日志可以使用mysqlbinlog命令查看。

mysqlbinlog [option] log-file1 log-file2...

以下是常用的幾個選項：

-d,--database=name：只查看指定數(shù)據(jù)庫的日志操作

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

-r,--result-file=name：將輸出的日志信息輸出到指定的文件中，使用重定向也一樣可以。

-s,--short-form：顯示簡單格式的日志，只記錄一些普通的語句，會省略掉一些額外的信息如位置信息和時間信息以及基于行的日志。可以用來調(diào)試，生產(chǎn)環(huán)境千萬不可使用

--set-charset=char_name：在輸出日志信息到文件中時，在文件第一行加上set names char_name

--start-datetime,--stop-datetime：指定輸出開始時間和結(jié)束時間內(nèi)的所有日志信息

--start-position=#,--stop-position=#：指定輸出開始位置和結(jié)束位置內(nèi)的所有日志信息

-v,-vv：顯示更詳細(xì)信息，基于row的日志默認(rèn)不會顯示出來，此時使用-v或-vv可以查看

在進(jìn)行測試之前，先對日志進(jìn)行一次刷新，以方便解釋二進(jìn)制日志的信息。

shell> mysqladmin -uroot -p refresh

假設(shè)現(xiàn)在的日志文件是mysql-bin.000001，里面暫時只有一些初始信息，沒有記錄任何操作過的記錄。

下面是每個二進(jìn)制日志文件的初始信息?？梢钥吹接涗浟藭r間和位置信息(at 4)。

[root@xuexi data]# 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*/;

現(xiàn)在在數(shù)據(jù)庫中執(zhí)行下面的操作：

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');

再查看二進(jìn)制日志信息。

[root@xuexi data]# 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到現(xiàn)在的總秒數(shù)時間戳，可以使用date -d '@1490736093'轉(zhuǎn)換。

• 位置0-120記錄的是二進(jìn)制日志的一些固定信息。
• 位置120-305記錄的是use和create table語句，語句的記錄時間為5:20:00。但注意，這里的use不是執(zhí)行的use語句，而是MySQL發(fā)現(xiàn)要操作的數(shù)據(jù)庫為test，而自動進(jìn)行的操作并記錄下來。人為的use語句是不會記錄的。
• 位置305-441記錄的是alter table語句，語句的記錄時間為5:20:21。
• 位置441-702記錄的是insert操作，因為該操作是DML語句，因此記錄了事務(wù)的開始BEGIN和提交COMMIT。
  • begin的起止位置為441-520；
  • insert into語句的起止位置為520-671，記錄的時間和自動開啟事務(wù)的begin時間是一樣的；
  • commit的起止位置為671-702。

使用-r命令將日志文件導(dǎo)入到指定文件中，使用重定向也可以實現(xiàn)同樣的結(jié)果。并使用-s查看簡化的日志文件。

[root@xuexi data]# mysqlbinlog mysql-bin.000001 -r /tmp/binlog.000001
[root@xuexi data]# mysqlbinlog mysql-bin.000001 -s>/tmp/binlog.sample

比較這兩個文件，看看簡化的日志文件簡化了哪些東西。

從上圖中可以看出，使用-s后，少了基于行的日志信息，也少了記錄的位置和時間信息。

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

[root@xuexi data]# 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可以只顯示指定數(shù)據(jù)庫相關(guān)的操作。例如先切換到其他數(shù)據(jù)庫進(jìn)行一番操作，然后再使用-d查看日志。

[root@xuexi data]# 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 ;
...后面固定部分省略...

可以看到，除了指定的mysql數(shù)據(jù)庫的信息輸出了，還非常簡化的輸出了其他數(shù)據(jù)庫的信息。

mysqlbinlog最有用的兩個選項就是指定時間和位置來輸出日志。

指定時間時，將輸出指定時間范圍內(nèi)的日志。指定的時間可以不和日志中記錄的日志相同。

[root@xuexi data]# 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 ;
...后面固定部分省略...

同理指定位置也一樣，但是指定位置時有個要求是如果指定起始位置，則必須指定日志文件中明確的起始位置。例如，日志文件中有位置120、305、441，可以指定起始和結(jié)束位置為120、500，但是不可以指定起止位置為150、500，因為日志文件中不存在150這個位置。

[root@xuexi data]# 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

該語句用于查看當(dāng)前使用了哪些二進(jìn)制日志文件。

可以通過查看二進(jìn)制的index文件來查看當(dāng)前正在使用哪些二進(jìn)制日志。

[root@xuexi data]# cat mysql-bin.index 
./mysql-bin.000003
./mysql-bin.000004
./mysql-bin.000005
./mysql-bin.000006

也可以在mysql環(huán)境中使用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

該語句用于查看日志中進(jìn)行了哪些操作。

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

可以指定起始位置。同樣，起始位置必須指定正確，不能指定不存在的位置。

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

該語句用于顯示主服務(wù)器中的二進(jìn)制日志信息。如果是主從結(jié)構(gòu)，它只會顯示主從結(jié)構(gòu)中主服務(wù)器的二進(jìn)制日志信息。

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

可以查看到當(dāng)前正在使用的日志及下一事件記錄的開始位置，還能查看到哪些數(shù)據(jù)庫需要記錄二進(jìn)制日志，哪些數(shù)據(jù)庫不記錄二進(jìn)制日志。

5.3 刪除二進(jìn)制日志

刪除二進(jìn)制日志有幾種方法。不管哪種方法，都會將刪除后的信息同步到二進(jìn)制index文件中。

1.reset master將會刪除所有日志，并讓日志文件重新從000001開始。

mysql> reset master;

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

purge master logs to "binlog_name.00000X"將會清空00000X之前的所有日志文件。例如刪除000006之前的日志文件。

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

master和binary是同義詞

purge master logs before 'yyyy-mm-dd hh:mi:ss'將會刪除指定日期之前的所有日志。但是若指定的時間處在正在使用中的日志文件中，將無法進(jìn)行purge。

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. |
+---------+------+---------------------------------------------------------------------------+

3.使用--expire_logs_days=N選項指定過了多少天日志自動過期清空。

5.4 二進(jìn)制日志的記錄格式

在MySQL 5.1之前，MySQL只有一種基于語句statement形式的日志記錄格式。即將所有的相關(guān)操作記錄為SQL語句形式。但是這樣的記錄方式對某些特殊信息無法同步記錄，例如uuid，now()等這樣動態(tài)變化的值。

從MySQL 5.1開始，MySQL支持statement、row、mixed三種形式的記錄方式。row形式是基于行來記錄，也就是將相關(guān)行的每一列的值都在日志中保存下來，這樣的結(jié)果會導(dǎo)致日志文件變得非常大，但是保證了動態(tài)值的確定性。還有一種mixed形式，表示如何記錄日志由MySQL自己來決定。

日志的記錄格式由變量binlog_format來指定。其值有：row,statement,mixed。innodb引擎的創(chuàng)始人之一在博客上推薦使用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()); 

查看產(chǎn)生的日志。

[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 ;
...后面固定部分省略...

發(fā)現(xiàn)是一堆看不懂的東西，使用-vv可將這些顯示出來。可以看出，結(jié)果中記錄的非常詳細(xì)，這也是為什么基于row記錄日志會導(dǎo)致日志文件極速變大。

[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模式。這種模式下默認(rèn)會采用statement的方式記錄，只有以下幾種情況會采用row的形式來記錄日志。

1.表的存儲引擎為NDB，這時對表的DML操作都會以row的格式記錄。

2.使用了uuid()、user()、current_user()、found_rows()、row_count()等不確定函數(shù)。但測試發(fā)現(xiàn)對now()函數(shù)仍會以statement格式記錄，而sysdate()函數(shù)會以row格式記錄。

3.使用了insert delay語句。

4.使用了臨時表。

5.5 二進(jìn)制日志相關(guān)的變量

注意：在配置binlog相關(guān)變量的時候，相關(guān)變量名總是搞混，因為有的是binlog，有的是log_bin，當(dāng)他們分開的時候，log在前，當(dāng)它們一起的時候，bin在前。在配置文件中也同樣如此。

• log_bin = {on | off | base_name} #指定是否啟用記錄二進(jìn)制日志或者指定一個日志路徑(路徑不能加.否則.后的被忽略)
• sql_log_bin ={ on | off } #指定是否啟用記錄二進(jìn)制日志，只有在log_bin開啟的時候才有效
• expire_logs_days = #指定自動刪除二進(jìn)制日志的時間，即日志過期時間
• binlog_do_db = #明確指定要記錄日志的數(shù)據(jù)庫
• binlog_ignore_db = #指定不記錄二進(jìn)制日志的數(shù)據(jù)庫
• log_bin_index = #指定mysql-bin.index文件的路徑
• binlog_format = { mixed | row | statement } #指定二進(jìn)制日志基于什么模式記錄
• binlog_rows_query_log_events = { 1|0 } # MySQL5.6.2添加了該變量，當(dāng)binlog format為row時，默認(rèn)不會記錄row對應(yīng)的SQL語句，設(shè)置為1或其他true布爾值時會記錄，但需要使用mysqlbinlog -v查看，這些語句是被注釋的，恢復(fù)時不會被執(zhí)行。
• max_binlog_size = #指定二進(jìn)制日志文件最大值，超出指定值將自動滾動。但由于事務(wù)不會跨文件，所以并不一定總是精確。
• binlog_cache_size = 32768 #基于事務(wù)類型的日志會先記錄在緩沖區(qū)，當(dāng)達(dá)到該緩沖大小時這些日志會寫入磁盤
• max_binlog_cache_size = #指定二進(jìn)制日志緩存最大大小，硬限制。默認(rèn)4G，夠大了，建議不要改
• binlog_cache_use：使用緩存寫二進(jìn)制日志的次數(shù)(這是一個實時變化的統(tǒng)計值)
• binlog_cache_disk_use:使用臨時文件寫二進(jìn)制日志的次數(shù)，當(dāng)日志超過了binlog_cache_size的時候會使用臨時文件寫日志，如果該變量值不為0，則考慮增大binlog_cache_size的值
• binlog_stmt_cache_size = 32768 #一般等同于且決定binlog_cache_size大小，所以修改緩存大小時只需修改這個而不用修改binlog_cache_size
• binlog_stmt_cache_use：使用緩存寫二進(jìn)制日志的次數(shù)
• binlog_stmt_cache_disk_use: 使用臨時文件寫二進(jìn)制日志的次數(shù)，當(dāng)日志超過了binlog_cache_size的時候會使用臨時文件寫日志，如果該變量值不為0，則考慮增大binlog_cache_size的值
• sync_binlog = { 0 | n } #這個參數(shù)直接影響mysql的性能和完整性
  • sync_binlog=0:不同步，日志何時刷到磁盤由FileSystem決定，這個性能最好。
  • sync_binlog=n:每寫n次事務(wù)(注意，對于非事務(wù)表來說，是n次事件，對于事務(wù)表來說，是n次事務(wù)，而一個事務(wù)里可能包含多個二進(jìn)制事件)，MySQL將執(zhí)行一次磁盤同步指令fdatasync()將緩存日志刷新到磁盤日志文件中。Mysql中默認(rèn)的設(shè)置是sync_binlog=0，即不同步，這時性能最好，但風(fēng)險最大。一旦系統(tǒng)奔潰，緩存中的日志都會丟失。

在innodb的主從復(fù)制結(jié)構(gòu)中，如果啟用了二進(jìn)制日志(幾乎都會啟用)，要保證事務(wù)的一致性和持久性的時候，必須將sync_binlog的值設(shè)置為1，因為每次事務(wù)提交都會寫入二進(jìn)制日志，設(shè)置為1就保證了每次事務(wù)提交時二進(jìn)制日志都會寫入到磁盤中，從而立即被從服務(wù)器復(fù)制過去。

5.6 二進(jìn)制日志定點還原數(shù)據(jù)庫

只需指定二進(jìn)制日志的起始位置（可指定終止位置）并將其保存到sql文件中，由mysql命令來載入恢復(fù)即可。當(dāng)然直接通過管道送給mysql命令也可。

至于是基于位置來恢復(fù)還是基于時間點來恢復(fù)，這兩種行為都可以。選擇時間點來恢復(fù)比較直觀些，并且跨日志文件恢復(fù)時更方便。

mysqlbinlog --stop-datetime="2014-7-2 15:27:48" /tmp/mysql-bin.000008 | mysql -u user -p password

恢復(fù)多個二進(jìn)制日志文件時：

mysqlbinlog mysql-bin.[*] | mysql -uroot -p password

或者將它們導(dǎo)入到一個文件中后恢復(fù)。

mysqlbinlog mysql-bin.000001 > /tmp/a.sql
mysqlbinlog mysql-bin.000002 >>/tmp/a.sql
mysql -u root -p password -e "source /tmp/a.sql"

總結(jié)

到此這篇關(guān)于MySQL日志的文章就介紹到這了,更多相關(guān)MySQL日志分析內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

最新評論