MySQL日志的詳細分析實例
前言
官方手冊:https://dev.mysql.com/doc/refman/5.7/en/server-logs.html
不管是哪個數(shù)據(jù)庫產(chǎn)品，一定會有日志文件。在MariaDB/MySQL中，主要有5種日志文件：
1.錯誤日志(error log)：記錄mysql服務的啟停時正確和錯誤的信息，還記錄啟動、停止、運行過程中的錯誤信息。
2.查詢日志(general log)：記錄建立的客戶端連接和執(zhí)行的語句。
3.二進制日志(bin log)：記錄所有更改數(shù)據(jù)的語句，可用于數(shù)據(jù)復制。
4.慢查詢日志(slow log)：記錄所有執(zhí)行時間超過long_query_time的所有查詢或不使用索引的查詢。
5.中繼日志(relay log)：主從復制時使用的日志。
除了這5種日志，在需要的時候還會創(chuàng)建DDL日志。本文暫先討論錯誤日志、一般查詢日志、慢查詢日志和二進制日志，中繼日志和主從復制有關，將在復制的章節(jié)中介紹。下一篇文章將介紹innodb事務日志，見：MySQL的事務日志。
1.日志刷新操作
以下操作會刷新日志文件，刷新日志文件時會關閉舊的日志文件并重新打開日志文件。對于有些日志類型，如二進制日志，刷新日志會滾動日志文件，而不僅僅是關閉并重新打開。
mysql> FLUSH LOGS; shell> mysqladmin flush-logs shell> mysqladmin refresh
2.錯誤日志
錯誤日志是最重要的日志之一，它記錄了MariaDB/MySQL服務啟動和停止正確和錯誤的信息，還記錄了mysqld實例運行過程中發(fā)生的錯誤事件信息。
可以使用"--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結尾)，并創(chuàng)建一個新的錯誤日志文件并打開，在MySQL 5.5.7之后，執(zhí)行刷新日志的操作時，錯誤日志會關閉并重新打開，如果錯誤日志不存在，則會先創(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.一般查詢日志
查詢日志分為一般查詢日志和慢查詢日志，它們是通過查詢是否超出變量long_query_time指定時間的值來判定的。在超時時間內完成的查詢是一般查詢，可以將其記錄到一般查詢日志中，但是建議關閉這種日志（默認是關閉的），超出時間的查詢是慢查詢，可以將其記錄到慢查詢日志中。
使用"--general_log={0|1}"來決定是否啟用一般查詢日志，使用"--general_log_file=file_name"來指定查詢日志的路徑。不給定路徑時默認的文件名以`hostname`.log命名。
和查詢日志有關的變量有：
long_query_time = 10 # 指定慢查詢超時時長，超出此時長的屬于慢查詢，會記錄到慢查詢日志中
log_output={TABLE|FILE|NONE} # 定義一般查詢日志和慢查詢日志的輸出格式，不指定時默認為fileTABLE表示記錄日志到表中，F(xiàn)ILE表示記錄日志到文件中，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版本開始已經(jīng)廢棄了該選項。
默認沒有開啟一般查詢日志，也不建議開啟一般查詢日志。此處打開該類型的日志，看看是如何記錄一般查詢日志的。
首先開啟一般查詢日志。
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;
查看一般查詢日志的內容。
[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記錄慢查詢日志是在查詢執(zhí)行完畢且已經(jīng)完全釋放鎖之后才記錄的，因此慢查詢日志記錄的順序和執(zhí)行的SQL查詢語句順序可能會不一致(例如語句1先執(zhí)行，查詢速度慢，語句2后執(zhí)行，但查詢速度快，則語句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 # 查詢沒有使用索引的時候是否也記入慢查詢日志現(xiàn)在啟用慢查詢日志。
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替換數(shù)字，S替換字符串 -g PATTERN grep: only consider stmts that include this string：通過grep來篩選select語句。
該工具歸類的時候，默認會將同文本但變量值不同的查詢語句視為同一類，并使用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)
顯然，這里歸類后的結果只是精確到0.01秒的，如果想要顯示及其精確的秒數(shù)，則使用-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語句調優(yōu)的時候非常有用，應該將它啟用起來，且應該讓慢查詢閾值盡量小，例如1秒甚至低于1秒。就像一天執(zhí)行上千次的1秒語句，和一天執(zhí)行幾次的20秒語句，顯然更值得去優(yōu)化這個1秒的語句。
5.二進制日志
5.1 二進制日志文件
二進制日志包含了引起或可能引起數(shù)據(jù)庫改變(如delete語句但沒有匹配行)的事件信息，但絕不會包括select和show這樣的查詢語句。語句以"事件"的形式保存，所以包含了時間、事件開始和結束位置等信息。
二進制日志是以事件形式記錄的，不是事務日志(但可能是基于事務來記錄二進制日志)，不代表它只記錄innodb日志，myisam表也一樣有二進制日志。
對于事務表的操作，二進制日志只在事務提交的時候一次性寫入(基于事務的innodb二進制日志)，提交前的每個二進制日志記錄都先cache，提交時寫入。
所以，對于事務表來說，一個事務中可能包含多條二進制日志事件，它們會在提交時一次性寫入。而對于非事務表的操作，每次執(zhí)行完語句就直接寫入。
MariaDB/MySQL默認沒有啟動二進制日志，要啟用二進制日志使用--log-bin=[on|off|file_name]選項指定，如果沒有給定file_name，則默認為datadir下的主機名加"-bin"，并在后面跟上一串數(shù)字表示日志序列號，如果給定的日志文件中包含了后綴(logname.suffix)將忽略后綴部分。
或者在配置文件中的[mysqld]部分設置log-bin也可以。注意：對于mysql 5.7，直接啟動binlog可能會導致mysql服務啟動失敗，這時需要在配置文件中的mysqld為mysql實例分配server_id。
[mysqld] # server_id=1234 log-bin=[on|filename]
mysqld還創(chuàng)建一個二進制日志索引文件，當二進制日志文件滾動的時候會向該文件中寫入對應的信息。所以該文件包含所有使用的二進制日志文件的文件名。默認情況下該文件與二進制日志文件的文件名相同，擴展名為'.index'。要指定該文件的文件名使用--log-bin-index[=file_name]選項。當mysqld在運行時不應手動編輯該文件，免得mysqld變得混亂。
當重啟mysql服務或刷新日志或者達到日志最大值時，將滾動二進制日志文件，滾動日志時只修改日志文件名的數(shù)字序列部分。
二進制日志文件的最大值通過變量max_binlog_size設置(默認值為1G)。但由于二進制日志可能是基于事務來記錄的(如innodb表類型)，而事務是絕對不可能也不應該跨文件記錄的，如果正好二進制日志文件達到了最大值但事務還沒有提交則不會滾動日志，而是繼續(xù)增大日志，所以max_binlog_size指定的值和實際的二進制日志大小不一定相等。
因為二進制日志文件增長迅速，但官方說明因此而損耗的性能小于1%，且二進制目的是為了恢復定點數(shù)據(jù)庫和主從復制，所以出于安全和功能考慮，極不建議將二進制日志和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：只查看指定數(shù)據(jù)庫的日志操作
-o,--offset=#：忽略掉日志中的前n個操作命令
-r,--result-file=name：將輸出的日志信息輸出到指定的文件中，使用重定向也一樣可以。
-s,--short-form：顯示簡單格式的日志，只記錄一些普通的語句，會省略掉一些額外的信息如位置信息和時間信息以及基于行的日志?？梢杂脕碚{試，生產(chǎn)環(huán)境千萬不可使用
--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
假設現(xiàn)在的日志文件是mysql-bin.000001，里面暫時只有一些初始信息，沒有記錄任何操作過的記錄。
下面是每個二進制日志文件的初始信息?？梢钥吹接涗浟藭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');再查看二進制日志信息。
[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'轉換。
- 位置0-120記錄的是二進制日志的一些固定信息。
- 位置120-305記錄的是use和create table語句，語句的記錄時間為5:20:00。但注意，這里的use不是執(zhí)行的use語句，而是MySQL發(fā)現(xiàn)要操作的數(shù)據(jù)庫為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命令將日志文件導入到指定文件中，使用重定向也可以實現(xiàn)同樣的結果。并使用-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ù)庫相關的操作。例如先切換到其他數(shù)據(jù)庫進行一番操作，然后再使用-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最有用的兩個選項就是指定時間和位置來輸出日志。
指定時間時，將輸出指定時間范圍內的日志。指定的時間可以不和日志中記錄的日志相同。
[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環(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
該語句用于查看日志中進行了哪些操作。
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 | | | | +------------------+----------+--------------+------------------+-------------------+
可以查看到當前正在使用的日志及下一事件記錄的開始位置，還能查看到哪些數(shù)據(jù)庫需要記錄二進制日志，哪些數(shù)據(jù)庫不記錄二進制日志。
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()等這樣動態(tài)變化的值。
從MySQL 5.1開始，MySQL支持statement、row、mixed三種形式的記錄方式。row形式是基于行來記錄，也就是將相關行的每一列的值都在日志中保存下來，這樣的結果會導致日志文件變得非常大，但是保證了動態(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可將這些顯示出來?？梢钥闯?，結果中記錄的非常詳細，這也是為什么基于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()等不確定函數(shù)。但測試發(fā)現(xiàn)對now()函數(shù)仍會以statement格式記錄，而sysdate()函數(shù)會以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 = #明確指定要記錄日志的數(shù)據(jù)庫
- binlog_ignore_db = #指定不記錄二進制日志的數(shù)據(jù)庫
- 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查看，這些語句是被注釋的，恢復時不會被執(zhí)行。
- max_binlog_size = #指定二進制日志文件最大值，超出指定值將自動滾動。但由于事務不會跨文件，所以并不一定總是精確。
- binlog_cache_size = 32768 #基于事務類型的日志會先記錄在緩沖區(qū)，當達到該緩沖大小時這些日志會寫入磁盤
- max_binlog_cache_size = #指定二進制日志緩存最大大小，硬限制。默認4G，夠大了，建議不要改
- binlog_cache_use：使用緩存寫二進制日志的次數(shù)(這是一個實時變化的統(tǒng)計值)
- binlog_cache_disk_use:使用臨時文件寫二進制日志的次數(shù)，當日志超過了binlog_cache_size的時候會使用臨時文件寫日志，如果該變量值不為0，則考慮增大binlog_cache_size的值
- binlog_stmt_cache_size = 32768 #一般等同于且決定binlog_cache_size大小，所以修改緩存大小時只需修改這個而不用修改binlog_cache_size
- binlog_stmt_cache_use：使用緩存寫二進制日志的次數(shù)
- binlog_stmt_cache_disk_use: 使用臨時文件寫二進制日志的次數(shù)，當日志超過了binlog_cache_size的時候會使用臨時文件寫日志，如果該變量值不為0，則考慮增大binlog_cache_size的值
- sync_binlog = { 0 | n } #這個參數(shù)直接影響mysql的性能和完整性
- sync_binlog=0:不同步，日志何時刷到磁盤由FileSystem決定，這個性能最好。
- sync_binlog=n:每寫n次事務(注意，對于非事務表來說，是n次事件，對于事務表來說，是n次事務，而一個事務里可能包含多個二進制事件)，MySQL將執(zhí)行一次磁盤同步指令fdatasync()將緩存日志刷新到磁盤日志文件中。Mysql中默認的設置是sync_binlog=0，即不同步，這時性能最好，但風險最大。一旦系統(tǒng)奔潰，緩存中的日志都會丟失。
在innodb的主從復制結構中，如果啟用了二進制日志(幾乎都會啟用)，要保證事務的一致性和持久性的時候，必須將sync_binlog的值設置為1，因為每次事務提交都會寫入二進制日志，設置為1就保證了每次事務提交時二進制日志都會寫入到磁盤中，從而立即被從服務器復制過去。
5.6 二進制日志定點還原數(shù)據(jù)庫
只需指定二進制日志的起始位置（可指定終止位置）并將其保存到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日志分析內容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關文章希望大家以后多多支持腳本之家！
相關文章
這篇文章主要介紹了MySQL如何快速導入數(shù)據(jù)，幫助大家更好的理解和學習MySQL，感興趣的朋友可以了解下2020-08-08
MySQL5.7安裝過程并重置root密碼的方法（shell 腳本）
由于 MySQL 5.7 版本的 root 密碼是首次啟動時隨機生成的，并且還要求必須修改后才能使用。下面小編給大家分享使用shell 腳本完成安裝和設置新的 root 密碼的方法，一起看看吧2016-12-12
MySQL多表關聯(lián)on和where速度對比實測看誰更快
這篇文章主要介紹了MySQL多表關聯(lián)on和where速度對比實測看誰更快問題，具有很好的參考價值，希望對大家有所幫助。如有錯誤或未考慮完全的地方，望不吝賜教2023-03-03
這篇文章主要介紹了mysql 8.0.17 安裝與使用教程圖解，本文圖文并茂給大家介紹的非常詳細，具有一定的參考借鑒價值,需要的朋友可以參考下2019-08-08
MySQL事務日志(redo?log和undo?log)的詳細分析
innodb事務日志包括redo?log和undo?log,redo?log是重做日志,提供前滾操作,undo?log是回滾日志，提供回滾操作,下面這篇文章主要給大家介紹了關于MySQL事務日志(redo?log和undo?log)的詳細分析,需要的朋友可以參考下2022-04-04
毫不夸張的說，有一半以上的死鎖問題由唯一索引貢獻，后面介紹的很多死鎖的問題都跟唯一索引有關。這次我們講一段唯一索引 S 鎖與 X 鎖的案例，下面小編來和大家一起學習一下2019-05-05
Navicat Premiun遠程連接MySQL報錯10038解決方案
這篇文章主要介紹了Navicat Premiun遠程連接MySQL報錯10038解決方案,文中通過示例代碼介紹的非常詳細，對大家的學習或者工作具有一定的參考學習價值,需要的朋友可以參考下2020-11-11
MySQL中的 inner join 和 left join的區(qū)別解析
這篇文章主要介紹了MySQL中的 inner join 和 left join的區(qū)別解析,本文通過場景描述給大家介紹的非常詳細，對大家的學習或工作具有一定的參考借鑒價值，需要的朋友可以參考下2023-05-05
這篇文章主要介紹了MySQL給查詢記錄增加序列號的實現(xiàn)方法,文中通過代碼示例講解的非常詳細,對大家的學習或工作有一定的參考價值,需要的朋友可以參考下2023-11-11
MySQL5.7中的sql_mode默認值帶來的坑及解決方法
這篇文章主要介紹了MySQL5.7中的sql_mode默認值帶來的坑及解決方法,非常不錯，具有一定的參考借鑒價值，需要的朋友可以參考下2018-11-11