MySQL紀錄檔的詳細分析範例

2022-04-15 13:01:27

前言

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

不管是哪個資料庫產品，一定會有紀錄檔檔案。在MariaDB/MySQL中，主要有5種紀錄檔檔案：

1.錯誤紀錄檔(error log)：記錄mysql服務的啟停時正確和錯誤的資訊，還記錄啟動、停止、執行過程中的錯誤資訊。

2.查詢紀錄檔(general log)：記錄建立的使用者端連線和執行的語句。

3.二進位制紀錄檔(bin log)：記錄所有更改資料的語句，可用於資料複製。

4.慢查詢紀錄檔(slow log)：記錄所有執行時間超過long_query_time的所有查詢或不使用索引的查詢。

5.中繼紀錄檔(relay log)：主從複製時使用的紀錄檔。

除了這5種紀錄檔，在需要的時候還會建立DDL紀錄檔。本文暫先討論錯誤紀錄檔、一般查詢紀錄檔、慢查詢紀錄檔和二進位制紀錄檔，中繼紀錄檔和主從複製有關，將在複製的章節中介紹。下一篇文章將介紹innodb事務紀錄檔，見：MySQL的事務紀錄檔。

1.紀錄檔重新整理操作

以下操作會重新整理紀錄檔檔案，重新整理紀錄檔檔案時會關閉舊的紀錄檔檔案並重新開啟紀錄檔檔案。對於有些紀錄檔型別，如二進位制紀錄檔，重新整理紀錄檔會捲動紀錄檔檔案，而不僅僅是關閉並重新開啟。

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

2.錯誤紀錄檔

錯誤紀錄檔是最重要的紀錄檔之一，它記錄了MariaDB/MySQL服務啟動和停止正確和錯誤的資訊，還記錄了mysqld範例執行過程中發生的錯誤事件資訊。

可以使用"--log-error=[file_name]"來指定mysqld記錄的錯誤紀錄檔檔案，如果沒有指定file_name，則預設的錯誤紀錄檔檔案為datadir目錄下的`hostname`.err，hostname表示當前的主機名。

也可以在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結尾)，並建立一個新的錯誤紀錄檔檔案並開啟，在MySQL 5.5.7之後，執行重新整理紀錄檔的操作時，錯誤紀錄檔會關閉並重新開啟，如果錯誤紀錄檔不存在，則會先建立。

在MariaDB/MySQL正在執行狀態下刪除錯誤紀錄檔後，不會自動建立錯誤紀錄檔，只有在重新整理紀錄檔的時候才會建立一個新的錯誤紀錄檔檔案。

以下是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.一般查詢紀錄檔

查詢紀錄檔分為一般查詢紀錄檔和慢查詢紀錄檔，它們是通過查詢是否超出變數long_query_time指定時間的值來判定的。在超時時間內完成的查詢是一般查詢，可以將其記錄到一般查詢紀錄檔中，但是建議關閉這種紀錄檔（預設是關閉的），超出時間的查詢是慢查詢，可以將其記錄到慢查詢紀錄檔中。

使用"--general_log={0|1}"來決定是否啟用一般查詢紀錄檔，使用"--general_log_file=file_name"來指定查詢紀錄檔的路徑。不給定路徑時預設的檔名以`hostname`.log命名。

和查詢紀錄檔有關的變數有：

long_query_time = 10 # 指定慢查詢超時時長，超出此時長的屬於慢查詢，會記錄到慢查詢紀錄檔中
log_output={TABLE|FILE|NONE}  # 定義一般查詢紀錄檔和慢查詢紀錄檔的輸出格式，不指定時預設為file

TABLE表示記錄紀錄檔到表中，FILE表示記錄紀錄檔到檔案中，NONE表示不記錄紀錄檔。只要這裡指定為NONE，即使開啟了一般查詢紀錄檔和慢查詢紀錄檔，也都不會有任何記錄。

和一般查詢紀錄檔相關的變數有：

general_log=off # 是否啟用一般查詢紀錄檔，為全域性變數，必須在global上修改。
sql_log_off=off # 在session級別控制是否啟用一般查詢紀錄檔，預設為off，即啟用
general_log_file=/mydata/data/hostname.log  # 預設是庫檔案路徑下主機名加上.log

在MySQL 5.6以前的版本還有一個"log"變數也是決定是否開啟一般查詢紀錄檔的。在5.6版本開始已經廢棄了該選項。

預設沒有開啟一般查詢紀錄檔，也不建議開啟一般查詢紀錄檔。此處開啟該型別的紀錄檔，看看是如何記錄一般查詢紀錄檔的。

首先開啟一般查詢紀錄檔。

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

執行幾個語句。

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;

檢視一般查詢紀錄檔的內容。

[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

由此可知，一般查詢紀錄檔查詢的不止是select語句，幾乎所有的語句都會記錄。

4.慢查詢紀錄檔

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

mysql記錄慢查詢紀錄檔是在查詢執行完畢且已經完全釋放鎖之後才記錄的，因此慢查詢紀錄檔記錄的順序和執行的SQL查詢語句順序可能會不一致(例如語句1先執行，查詢速度慢，語句2後執行，但查詢速度快，則語句2先記錄)。

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

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

和慢查詢有關的變數：

long_query_time=10 # 指定慢查詢超時時長(預設10秒)，超出此時長的屬於慢查詢
log_output={TABLE|FILE|NONE} # 定義一般查詢紀錄檔和慢查詢紀錄檔的輸出格式，預設為file
log_slow_queries={yes|no}    # 是否啟用慢查詢紀錄檔，預設不啟用
slow_query_log={1|ON|0|OFF}  # 也是是否啟用慢查詢紀錄檔，此變數和log_slow_queries修改一個另一個同時變化
slow_query_log_file=/mydata/data/hostname-slow.log  #預設路徑為庫檔案目錄下主機名加上-slow.log
log_queries_not_using_indexes=OFF # 查詢沒有使用索引的時候是否也記入慢查詢紀錄檔

現在啟用慢查詢紀錄檔。

mysql> set @@global.slow_query_log=on;

因為預設超時時長為10秒，所以進行一個10秒的查詢。

mysql> select sleep(10);

檢視慢查詢紀錄檔檔案。這裡看到雖然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);

隨著時間的推移，慢查詢紀錄檔檔案中的記錄可能會變得非常多，這對於分析查詢來說是非常困難的。好在提供了一個專門歸類慢查詢紀錄檔的工具mysqldumpslow。

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

該工具歸類的時候，預設會將同文字但變數值不同的查詢語句視為同一類，並使用N代替其中的數值變數，使用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)

顯然，這裡歸類後的結果只是精確到0.01秒的，如果想要顯示及其精確的秒數，則使用-d選項啟用偵錯功能。

[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語句調優的時候非常有用，應該將它啟用起來，且應該讓慢查詢閾值儘量小，例如1秒甚至低於1秒。就像一天執行上千次的1秒語句，和一天執行幾次的20秒語句，顯然更值得去優化這個1秒的語句。

5.二進位制紀錄檔

5.1 二進位制紀錄檔檔案

二進位制紀錄檔包含了引起或可能引起資料庫改變(如delete語句但沒有匹配行)的事件資訊，但絕不會包括select和show這樣的查詢語句。語句以"事件"的形式儲存，所以包含了時間、事件開始和結束位置等資訊。

二進位制紀錄檔是以事件形式記錄的，不是事務紀錄檔(但可能是基於事務來記錄二進位制紀錄檔)，不代表它只記錄innodb紀錄檔，myisam表也一樣有二進位制紀錄檔。

對於事務表的操作，二進位制紀錄檔只在事務提交的時候一次性寫入(基於事務的innodb二進位制紀錄檔)，提交前的每個二進位制紀錄檔記錄都先cache，提交時寫入。

所以，對於事務表來說，一個事務中可能包含多條二進位制紀錄檔事件，它們會在提交時一次性寫入。而對於非事務表的操作，每次執行完語句就直接寫入。

MariaDB/MySQL預設沒有啟動二進位制紀錄檔，要啟用二進位制紀錄檔使用--log-bin=[on|off|file_name]選項指定，如果沒有給定file_name，則預設為datadir下的主機名加"-bin"，並在後面跟上一串數位表示紀錄檔序列號，如果給定的紀錄檔檔案中包含了字尾(logname.suffix)將忽略字尾部分。

或者在組態檔中的[mysqld]部分設定log-bin也可以。注意：對於mysql 5.7，直接啟動binlog可能會導致mysql服務啟動失敗，這時需要在組態檔中的mysqld為mysql範例分配server_id。

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

mysqld還建立一個二進位制紀錄檔索引檔案，當二進位制紀錄檔檔案卷動的時候會向該檔案中寫入對應的資訊。所以該檔案包含所有使用的二進位制紀錄檔檔案的檔名。預設情況下該檔案與二進位制紀錄檔檔案的檔名相同，擴充套件名為'.index'。要指定該檔案的檔名使用--log-bin-index[=file_name]選項。當mysqld在執行時不應手動編輯該檔案，免得mysqld變得混亂。

當重啟mysql服務或重新整理紀錄檔或者達到紀錄檔最大值時，將捲動二進位制紀錄檔檔案，捲動紀錄檔時只修改紀錄檔檔名的數位序列部分。

二進位制紀錄檔檔案的最大值通過變數max_binlog_size設定(預設值為1G)。但由於二進位制紀錄檔可能是基於事務來記錄的(如innodb表型別)，而事務是絕對不可能也不應該跨檔案記錄的，如果正好二進位制紀錄檔檔案達到了最大值但事務還沒有提交則不會捲動紀錄檔，而是繼續增大紀錄檔，所以max_binlog_size指定的值和實際的二進位制紀錄檔大小不一定相等。

因為二進位制紀錄檔檔案增長迅速，但官方說明因此而損耗的效能小於1%，且二進位制目的是為了恢復定點資料庫和主從複製，所以出於安全和功能考慮，極不建議將二進位制紀錄檔和datadir放在同一磁碟上。

5.2 檢視二進位制紀錄檔

MySQL中檢視二進位制紀錄檔的方法主要有幾種。

1.使用mysqlbinlog工具。

2.使用show顯示對應的資訊。

SHOW {BINARY | MASTER} LOGS      # 檢視使用了哪些紀錄檔檔案
SHOW BINLOG EVENTS [IN 'log_name'] [FROM pos]   # 檢視紀錄檔中進行了哪些操作
SHOW MASTER STATUS         # 顯式主伺服器中的二進位制紀錄檔資訊

5.2.1 mysqlbinlog

二進位制紀錄檔可以使用mysqlbinlog命令檢視。

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

以下是常用的幾個選項：

-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：指定輸出開始時間和結束時間內的所有紀錄檔資訊

--start-position=#,--stop-position=#：指定輸出開始位置和結束位置內的所有紀錄檔資訊

-v,-vv：顯示更詳細資訊，基於row的紀錄檔預設不會顯示出來，此時使用-v或-vv可以檢視

在進行測試之前，先對紀錄檔進行一次重新整理，以方便解釋二進位制紀錄檔的資訊。

shell> mysqladmin -uroot -p refresh

假設現在的紀錄檔檔案是mysql-bin.000001，裡面暫時只有一些初始資訊，沒有記錄任何操作過的記錄。

下面是每個二進位制紀錄檔檔案的初始資訊。可以看到記錄了時間和位置資訊(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*/;

現在在資料庫中執行下面的操作：

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

再檢視二進位制紀錄檔資訊。

[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到現在的總秒數時間戳，可以使用date -d '@1490736093'轉換。

位置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檢視簡化的紀錄檔檔案。

[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可以只顯示指定資料庫相關的操作。例如先切換到其他資料庫進行一番操作，然後再使用-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資料庫的資訊輸出了，還非常簡化的輸出了其他資料庫的資訊。

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

指定時間時，將輸出指定時間範圍內的紀錄檔。指定的時間可以不和紀錄檔中記錄的紀錄檔相同。

[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，可以指定起始和結束位置為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

該語句用於檢視當前使用了哪些二進位制紀錄檔檔案。

可以通過檢視二進位制的index檔案來檢視當前正在使用哪些二進位制紀錄檔。

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

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

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 { 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'將會刪除指定日期之前的所有紀錄檔。但是若指定的時間處在正在使用中的紀錄檔檔案中，將無法進行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 二進位制紀錄檔的記錄格式

在MySQL 5.1之前，MySQL只有一種基於語句statement形式的紀錄檔記錄格式。即將所有的相關操作記錄為SQL語句形式。但是這樣的記錄方式對某些特殊資訊無法同步記錄，例如uuid，now()等這樣動態變化的值。

從MySQL 5.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的形式來記錄紀錄檔。

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

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

3.使用了insert delay語句。

4.使用了臨時表。

5.5 二進位制紀錄檔相關的變數

注意：在設定binlog相關變數的時候，相關變數名總是搞混，因為有的是binlog，有的是log_bin，當他們分開的時候，log在前，當它們一起的時候，bin在前。在組態檔中也同樣如此。

log_bin = {on | off | base_name} #指定是否啟用記錄二進位制紀錄檔或者指定一個紀錄檔路徑(路徑不能加.否則.後的被忽略)
sql_log_bin ={ on | off } #指定是否啟用記錄二進位制紀錄檔，只有在log_bin開啟的時候才有效
expire_logs_days = #指定自動刪除二進位制紀錄檔的時間，即紀錄檔過期時間
binlog_do_db = #明確指定要記錄紀錄檔的資料庫
binlog_ignore_db = #指定不記錄二進位制紀錄檔的資料庫
log_bin_index = #指定mysql-bin.index檔案的路徑
binlog_format = { mixed | row | statement } #指定二進位制紀錄檔基於什麼模式記錄
binlog_rows_query_log_events = { 1|0 } # MySQL5.6.2新增了該變數，當binlog format為row時，預設不會記錄row對應的SQL語句，設定為1或其他true布林值時會記錄，但需要使用mysqlbinlog -v檢視，這些語句是被註釋的，恢復時不會被執行。
max_binlog_size = #指定二進位制紀錄檔檔案最大值，超出指定值將自動捲動。但由於事務不會跨檔案，所以並不一定總是精確。
binlog_cache_size = 32768 #基於事務型別的紀錄檔會先記錄在緩衝區，當達到該緩衝大小時這些紀錄檔會寫入磁碟
max_binlog_cache_size = #指定二進位制紀錄檔快取最大大小，硬限制。預設4G，夠大了，建議不要改
binlog_cache_use：使用快取寫二進位制紀錄檔的次數(這是一個實時變化的統計值)
binlog_cache_disk_use:使用臨時檔案寫二進位制紀錄檔的次數，當紀錄檔超過了binlog_cache_size的時候會使用臨時檔案寫紀錄檔，如果該變數值不為0，則考慮增大binlog_cache_size的值
binlog_stmt_cache_size = 32768 #一般等同於且決定binlog_cache_size大小，所以修改快取大小時只需修改這個而不用修改binlog_cache_size
binlog_stmt_cache_use：使用快取寫二進位制紀錄檔的次數
binlog_stmt_cache_disk_use: 使用臨時檔案寫二進位制紀錄檔的次數，當紀錄檔超過了binlog_cache_size的時候會使用臨時檔案寫紀錄檔，如果該變數值不為0，則考慮增大binlog_cache_size的值
sync_binlog = { 0 | n } #這個引數直接影響mysql的效能和完整性
- sync_binlog=0:不同步，紀錄檔何時刷到磁碟由FileSystem決定，這個效能最好。
- sync_binlog=n:每寫n次事務(注意，對於非事務表來說，是n次事件，對於事務表來說，是n次事務，而一個事務裡可能包含多個二進位制事件)，MySQL將執行一次磁碟同步指令fdatasync()將快取紀錄檔重新整理到磁碟紀錄檔檔案中。Mysql中預設的設定是sync_binlog=0，即不同步，這時效能最好，但風險最大。一旦系統奔潰，快取中的紀錄檔都會丟失。

在innodb的主從複製結構中，如果啟用了二進位制紀錄檔(幾乎都會啟用)，要保證事務的一致性和永續性的時候，必須將sync_binlog的值設定為1，因為每次事務提交都會寫入二進位制紀錄檔，設定為1就保證了每次事務提交時二進位制紀錄檔都會寫入到磁碟中，從而立即被從伺服器複製過去。

5.6 二進位制紀錄檔定點還原資料庫

只需指定二進位制紀錄檔的起始位置（可指定終止位置）並將其儲存到sql檔案中，由mysql命令來載入恢復即可。當然直接通過管道送給mysql命令也可。

至於是基於位置來恢復還是基於時間點來恢復，這兩種行為都可以。選擇時間點來恢復比較直觀些，並且跨紀錄檔檔案恢復時更方便。

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

恢復多個二進位制紀錄檔檔案時：

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

或者將它們匯入到一個檔案中後恢復。

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

總結

到此這篇關於MySQL紀錄檔的文章就介紹到這了,更多相關MySQL紀錄檔分析內容請搜尋it145.com以前的文章或繼續瀏覽下面的相關文章希望大家以後多多支援it145.com！