詳細分析MySQL的日志(一)


官方手冊: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查看日志。

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

[root@xuexi data]# 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最有用的兩個選項就是指定時間和位置來輸出日志。

指定時間時,將輸出指定時間范圍內的日志。指定的時間可以不和日志中記錄的日志相同。

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

同理指定位置也一樣,但是指定位置時有個要求是如果指定起始位置,則必須指定日志文件中明確的起始位置。例如,日志文件中有位置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"


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM