MySQL手動(dòng)注冊(cè)binlog文件造成主從異常的原因
更新時(shí)間：2020年10月14日 14:22:30 作者：重慶八怪
這篇文章主要介紹了MySQL手動(dòng)注冊(cè)binlog文件造成主從異常的原因，幫助大家更好的理解和使用MySQL數(shù)據(jù)庫，感興趣的朋友可以了解下
一、問題來源
有一個(gè)朋友@水米田 問我，基于POSITION的主從。他做了如下的操作
將備份的一些binlog文件加入到了目錄中
修改index文件，加入了這些binlog文件
flush binary logs
然后整個(gè)主從環(huán)境大量延遲。
二、朋友的測(cè)試
下面是另外一個(gè)朋友@徐晨亮的測(cè)試：
master上：
(root:db1@xucl:10:30:22)[(none)]> show binary logs;
+---------------------+-----------+
| Log_name | File_size |
+---------------------+-----------+
| mysql-binlog.000031 | 1019 |
| mysql-binlog.000032 | 424 |
| mysql-binlog.000033 | 244 |
| mysql-binlog.000034 | 2332 |
| mysql-binlog.000035 | 2134 |
| mysql-binlog.000036 | 845915 |
| mysql-binlog.000037 | 11735 |
| mysql-binlog.000038 | 284 |
| mysql-binlog.000039 | 284 |
| mysql-binlog.000040 | 284 |
| mysql-binlog.000041 | 284 |
| mysql-binlog.000042 | 234 |
+---------------------+-----------+
12 rows in set (0.00 sec)
(root:db1@xucl:10:30:34)[(none)]> purge binary logs to 'mysql-binlog.000039';
Query OK, 0 rows affected (0.00 sec)
(root:db1@xucl:10:30:49)[(none)]> show binary logs;
+---------------------+-----------+
| Log_name | File_size |
+---------------------+-----------+
| mysql-binlog.000039 | 284 |
| mysql-binlog.000040 | 284 |
| mysql-binlog.000041 | 284 |
| mysql-binlog.000042 | 234 |
+---------------------+-----------+
4 rows in set (0.00 sec)
執(zhí)行插入數(shù)據(jù)
(root:db1@xucl:10:31:23)[xucl]> insert into t values(9,9);
將備份的binlog拷貝回原先的目錄并修改index文件進(jìn)行注冊(cè)
[root@izbp12nspj47ypto9t6vyez logs]# ll
總用量 884
-rw-r----- 1 mysql mysql 1019 5月 20 22:03 mysql-binlog.000031
-rw-r----- 1 mysql mysql 424 5月 20 22:03 mysql-binlog.000032
-rw-r----- 1 mysql mysql 244 5月 20 22:03 mysql-binlog.000033
-rw-r----- 1 mysql mysql 2332 5月 20 22:03 mysql-binlog.000034
-rw-r----- 1 mysql mysql 2134 5月 20 22:03 mysql-binlog.000035
-rw-r----- 1 mysql mysql 845915 5月 20 22:03 mysql-binlog.000036
-rw-r----- 1 mysql mysql 11735 5月 20 22:05 mysql-binlog.000037
-rw-r----- 1 mysql mysql 284 5月 20 22:06 mysql-binlog.000038
-rw-r----- 1 mysql mysql 284 5月 21 10:28 mysql-binlog.000039
-rw-r----- 1 mysql mysql 284 5月 21 10:28 mysql-binlog.000040
-rw-r----- 1 mysql mysql 284 5月 21 10:28 mysql-binlog.000041
-rw-r----- 1 mysql mysql 491 5月 21 10:31 mysql-binlog.000042
-rw-r----- 1 mysql mysql 204 5月 21 10:30 mysql-binlog.index
主庫flush binary logs
(root:db1@xucl:10:32:51)[(none)]> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
(root:db1@xucl:10:32:57)[(none)]> show binary logs;
+---------------------+-----------+
| Log_name | File_size |
+---------------------+-----------+
| mysql-binlog.000031 | 1019 |
| mysql-binlog.000032 | 424 |
| mysql-binlog.000033 | 244 |
| mysql-binlog.000034 | 2332 |
| mysql-binlog.000035 | 2134 |
| mysql-binlog.000036 | 845915 |
| mysql-binlog.000037 | 11735 |
| mysql-binlog.000038 | 284 |
| mysql-binlog.000039 | 284 |
| mysql-binlog.000040 | 284 |
| mysql-binlog.000041 | 284 |
| mysql-binlog.000042 | 541 |
| mysql-binlog.000043 | 234 |
+---------------------+-----------+
13 rows in set (0.00 sec)
此時(shí)，slave報(bào)錯(cuò)如下：
(root:db1@xucl:10:31:05)[(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: 127.0.0.1
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-binlog.000035
Read_Master_Log_Pos: 194
Relay_Log_File: izbp12nspj47ypto9t6vyez-relay-bin.000011
Relay_Log_Pos: 373
Relay_Master_Log_File: mysql-binlog.000035
Slave_IO_Running: No
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 194
Relay_Log_Space: 648
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate GTID-transaction when @@GLOBAL.GTID_MODE = OFF, at file /storage/single/mysql3306/logs/mysql-binlog.000035, position 194.; the first event 'mysql-binlog.000039' at 234, the last event read from '/storage/single/mysql3306/logs/mysql-binlog.000035' at 259, the last byte read from '/storage/single/mysql33'
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 3306
Master_UUID: e8bdf01a-c79b-11e8-82b3-00163e088352
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp: 190521 10:32:57
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set: 4c423515-6661-11e9-b767-00163e088352:1-7,
e8bdf01a-c79b-11e8-82b3-00163e088352:1-57192
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
從slave上的報(bào)錯(cuò)來看，在主庫flush binary logs后，從庫又讀取注冊(cè)的binlog并且又apply了
三、現(xiàn)象說明
從整個(gè)測(cè)試來看，MySQL視乎將手動(dòng)注冊(cè)的文件進(jìn)行了傳輸和應(yīng)用。報(bào)錯(cuò)是因?yàn)檫@個(gè)庫以前是GITD_MODE=ON的，但是測(cè)試的時(shí)候已經(jīng)關(guān)閉了GTID_MODE，改為了POSITION的模式，這個(gè)報(bào)錯(cuò)是因?yàn)镈UMP線程會(huì)進(jìn)行檢測(cè)：
這個(gè)圖來自我新寫的一個(gè)系列（暫時(shí)還沒發(fā)布，大概年底才能寫好）。不管怎么說，DUMP線程已經(jīng)在開始傳輸老的binlog文件了。那么原因是什么呢？下面我們將進(jìn)行解釋。
四、flush binary logs對(duì)binlog的操作
flush binary logs 將包含如下操作：
- 獲取新的binlog文件名字
- 關(guān)閉舊的binlog
- 關(guān)閉index file
- 打開index file
- 打開新的binlog
- 將新的binlog加入到indexfile
具體可以參考函數(shù)MYSQL_BIN_LOG::new_file_impl。其中要說明一下獲取新的binlog文件名字是通過函數(shù)find_uniq_filename實(shí)現(xiàn)的，其中包含如下代碼：
file_info= dir_info->dir_entry;
for (i= dir_info->number_off_files ; i-- ; file_info++)
{
if (strncmp(file_info->name, start, length) == 0 &&
is_number(file_info->name+length, &number,0))
{
set_if_bigger(max_found, number);
}
}
...
*next= (need_next || max_found == 0) ? max_found + 1 : max_found;
大概意思就是掃描index file文件里面的binlog文件，獲取其序號(hào)最高的一個(gè)，然后加1。棧幀如下：
#0 find_uniq_filename (name=0x7fffec5ec6d0 "/mysqldata/mysql3340/log/binlog", next=0x7fffec5ec678, need_next=true) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3679 #1 0x000000000187d208 in generate_new_log_name (new_name=0x7fffec5ec6d0 "/mysqldata/mysql3340/log/binlog", new_ext=0x0, log_name=0x7ffedc011520 "/mysqldata/mysql3340/log/binlog", is_binlog=true) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3767 #2 0x0000000001884fdb in MYSQL_BIN_LOG::new_file_impl (this=0x2e83640, need_lock_log=false, extra_description_event=0x0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7175 #3 0x0000000001884cbb in MYSQL_BIN_LOG::new_file_without_locking (this=0x2e83640, extra_description_event=0x0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7099 #4 0x0000000001886b6b in MYSQL_BIN_LOG::rotate (this=0x2e83640, force_rotate=true, check_purge=0x7fffec5ecbfb) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7775 #5 0x0000000001886d53 in MYSQL_BIN_LOG::rotate_and_purge (this=0x2e83640, thd=0x7ffedc000b90, force_rotate=true) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7846
因此即便我們手動(dòng)修改了index file，flush binary logs卻不會(huì)有問題，因?yàn)樗鼘?shí)際掃描了index file文件。
同時(shí)我們也看到flush binary logs重新加載了index file，這個(gè)時(shí)候手動(dòng)修改的index file就生效了，使用show binary logs就能查看到你加入的文件了。
五、主從問題的產(chǎn)生
binlog切換后，DUMP線程也需要讀取下一個(gè)binlog文件。我們來看看它是怎么確認(rèn)讀取哪一個(gè)文件的。
在函數(shù)sender.run()中可以找到循環(huán)每個(gè)binlog文件的代碼。下面一句是尋找下一個(gè)binlog文件：
int error= mysql_bin_log.find_next_log(&m_linfo, 0);
mysql_bin_log.find_next_log 包含的代碼：
my_b_seek(&index_file, linfo->index_file_offset);//進(jìn)行偏移量偏移 linfo->index_file_start_offset= linfo->index_file_offset; length=my_b_gets(&index_file, fname, FN_REFLEN));//讀取文件名字 ... if(normalize_binlog_name(full_fname, fname, is_relay_log)) ... linfo->index_file_offset= my_b_tell(&index_file);//偏移量從新記錄以備下一次使用
我們能夠看到DUMP線程并沒有實(shí)際掃描整個(gè)index文件，而是通過一個(gè)index文件的偏移量進(jìn)行讀取。如果手動(dòng)修改index文件那么偏移量就出現(xiàn)了錯(cuò)亂。因此DUMP發(fā)送的下一個(gè)文件將是不確定的。因此出現(xiàn)了發(fā)送手動(dòng)注冊(cè)的binlog文件給從庫的現(xiàn)象，這種情況下可能出現(xiàn)下面情況：
- 如果是GTID_MODE 關(guān)閉，使用POSITION那么這種情況一定報(bào)錯(cuò)，比如重復(fù)的行。
- 如果是GTID_MODE 和AUTO_POSITION=1，那么DUMP線程會(huì)進(jìn)行GTID的過濾不發(fā)送，因?yàn)镋vent不發(fā)送所以延遲會(huì)持續(xù)一段時(shí)間為0。
- 如果是GTID_MODE 和AUTO_POSITION=0，那么SQL線程應(yīng)用GITD_EVENT的時(shí)候會(huì)進(jìn)行過濾，延遲可能出現(xiàn)很大的情況。
盡管GTID可能可以屏蔽這種問題，但是DUMP線程已經(jīng)在考慮發(fā)送老的binlog文件了，這是不合適的。
六、purge binary logs能夠維護(hù)這個(gè)偏移量
為什么purge binary logs不會(huì)出現(xiàn)問題呢，因?yàn)樵趐urge binary logs的語句下，會(huì)維護(hù)這個(gè)偏移量如下：
virtual void operator()(THD *thd)
{
LOG_INFO* linfo;
mysql_mutex_lock(&thd->LOCK_thd_data);
if ((linfo= thd->current_linfo))//b binlog.cc:2829
{
/*
Index file offset can be less that purge offset only if
we just started reading the index file. In that case
we have nothing to adjust.
*/
if (linfo->index_file_offset < m_purge_offset)
linfo->fatal = (linfo->index_file_offset != 0);
else
linfo->index_file_offset -= m_purge_offset;
}
mysql_mutex_unlock(&thd->LOCK_thd_data);
我們可以看到linfo->index_file_offset -= m_purge_offset;這樣一個(gè)語句。下面是棧幀：
#0 Adjust_offset::operator() (this=0x7fffec5ec720, thd=0x7ffedc000be0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:2831 #1 0x0000000000eef320 in Do_THD::operator() (this=0x7fffec5ec6a0, thd=0x7ffedc000be0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/mysqld_thd_manager.cc:46 #2 0x0000000000eefa0f in std::for_each<THD**, Do_THD> (__first=0x3003358, __last=0x3003368, __f=...) at /usr/lib/gcc/x86_64-redhat-linux/4.4.7/../../../../include/c++/4.4.7/bits/stl_algo.h:4200 #3 0x0000000000eeefc0 in Global_THD_manager::do_for_all_thd (this=0x3003340, func=0x7fffec5ec720) at /mysqldata/percona-server-locks-detail-5.7.22/sql/mysqld_thd_manager.cc:273 #4 0x000000000187ae0a in adjust_linfo_offsets (purge_offset=0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:2873 #5 0x0000000001883239 in MYSQL_BIN_LOG::remove_logs_from_index (this=0x2e83640, log_info=0x7fffec5ec7d0, need_update_threads=true) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:6352 #6 0x0000000001883676 in MYSQL_BIN_LOG::purge_logs (this=0x2e83640, to_log=0x7fffec5eca80 "/mysqldata/mysql3340/log/binlog.000001", included=false, need_lock_index=true, need_update_threads=true, decrease_log_space=0x0, auto_purge=false) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:6469 #7 0x000000000187b4b5 in purge_master_logs (thd=0x7ffee0000c00, to_log=0x7ffee0006600 "binlog.000001") at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3127
七、測(cè)試POSITION模式下的報(bào)錯(cuò)
1、 環(huán)境
mysql> show binary logs;
+---------------+-----------+
| Log_name | File_size |
+---------------+-----------+
| binlog.000001 | 198 |
| binlog.000002 | 154 |
+---------------+-----------+
2 rows in set (0.00 sec)
mysql> show create table testcp \G;
*************************** 1. row ***************************
Table: testcp
Create Table: CREATE TABLE `testcp` (
`id` int(11) NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)
ERROR:
No query specified
2、執(zhí)行一個(gè)語句
主庫：
mysql> insert into testcp values(20); Query OK, 1 row affected (0.43 sec) mysql> select * from testcp; +----+ | id | +----+ | 10 | | 20 | +----+ 2 rows in set (0.01 sec)
從庫：
mysql> show slave status \G;
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.168.99.41
Master_User: repl
Master_Port: 3340
Connect_Retry: 60
Master_Log_File: binlog.000002
Read_Master_Log_Pos: 417
Relay_Log_File: relay.000004
Relay_Log_Pos: 624
Relay_Master_Log_File: binlog.000002
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
...
mysql> select * from testcp;
+----+
| id |
+----+
| 10 |
| 20 |
+----+
這個(gè)時(shí)候DUMP線程index file偏移指針如下：
3、主庫執(zhí)行purge binary logs
做之前拷貝原有binlog.000001為binlog.000001bak因?yàn)榈葧?huì)要拷貝回去
mysql> purge binary logs to 'binlog.000002'; Query OK, 0 rows affected (3.14 sec) mysql> show binary logs; +---------------+-----------+ | Log_name | File_size | +---------------+-----------+ | binlog.000002 | 417 | +---------------+-----------+ 1 row in set (0.00 sec)
因?yàn)閜urge binary logs命令會(huì)維護(hù)偏移指針，這個(gè)時(shí)候DUMP線程的index file偏移指針如下：
4、手動(dòng)更改
將binlog.000001bak拷貝為binlog.000001，然后修改index file將binlog.000001加入回去，然后flush binary logs如下：
mysql> flush binary logs; Query OK, 0 rows affected (0.15 sec) mysql> show binary logs; +---------------+-----------+ | Log_name | File_size | +---------------+-----------+ | binlog.000001 | 198 | | binlog.000002 | 461 | +---------------+-----------+ 2 rows in set (0.00 sec)
手動(dòng)完成這個(gè)工作并不會(huì)維護(hù)DUMP線程的index file偏移指針，因此如下：
就這樣DUMP線程重新發(fā)送了一次binlog.000002的內(nèi)容，POSITION的從庫只能報(bào)錯(cuò)了如下：
mysql> select * from replication_applier_status_by_worker \G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 1
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: ANONYMOUS
LAST_ERROR_NUMBER: 1062
LAST_ERROR_MESSAGE: Worker 1 failed executing transaction 'ANONYMOUS' at master log binlog.000002, end_log_pos 386; Could not execute Write_rows event on table testmts.testcp; Duplicate entry '20' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log binlog.000002, end_log_pos 386
LAST_ERROR_TIMESTAMP: 2019-05-21 14:46:26
八、總結(jié)
這種操作非常不規(guī)范，如果實(shí)在要這么做考慮如下步驟：
- 關(guān)閉全部的從庫
- 手動(dòng)注冊(cè)binlog文件，修改index 文件
- flush binary logs
- 啟動(dòng)從庫
這種情況下將會(huì)重新初始化DUMP的偏移量指針，應(yīng)該是沒有問題的。還是盡量不要考慮這么做。
以上就是MySQL手動(dòng)注冊(cè)binlog文件造成主從異常的原因的詳細(xì)內(nèi)容，更多關(guān)于MySQL 主從異常的資料請(qǐng)關(guān)注腳本之家其它相關(guān)文章！
相關(guān)文章
這篇文章主要介紹了mysql索引原理與用法,結(jié)合實(shí)例形式分析了mysql索引的基本概念、原理、用法及操作注意事項(xiàng),需要的朋友可以參考下2020-04-04
這篇文章主要介紹了解讀mysql datetime類型精確到毫秒、微秒的問題，具有很好的參考價(jià)值，希望對(duì)大家有所幫助。如有錯(cuò)誤或未考慮完全的地方，望不吝賜教2023-02-02
對(duì) MySQL 數(shù)據(jù)庫的查詢，除了基本的查詢外，有時(shí)候需要對(duì)查詢的結(jié)果集進(jìn)行處理。例如只取 10 條數(shù)據(jù)、對(duì)查詢結(jié)果進(jìn)行排序或分組等等，今天就給大家分享MySQL一些常用高級(jí)SQL語句，感興趣的朋友一起看看吧2021-07-07
Mysql中的超時(shí)時(shí)間設(shè)置方式
這篇文章主要介紹了Mysql中的超時(shí)時(shí)間設(shè)置方式,具有很好的參考價(jià)值,希望對(duì)大家有所幫助,如有錯(cuò)誤或未考慮完全的地方,望不吝賜教2024-01-01
本文給大家介紹Mac 安裝和卸載 Mysql5.7.11 的方法，本文介紹的非常詳細(xì)，具有參考借鑒價(jià)值，感興趣的朋友一起學(xué)習(xí)吧2016-03-03
Mysql 5.7.9 shutdown 語法實(shí)例詳解
之前如果想關(guān)閉一個(gè)mysql數(shù)據(jù)庫可以通過kill 命令、mysqladmin shutdown 、service mysqld stop 等這樣的方式。然而在mysql-5.7.9之后mysql終于提供了SQL接口的shutdown語法啦2017-06-06
mysql實(shí)現(xiàn)模糊查詢并按匹配程度排序
這篇文章主要介紹了mysql實(shí)現(xiàn)模糊查詢并按匹配程度排序方式,具有很好的參考價(jià)值,希望對(duì)大家有所幫助,如有錯(cuò)誤或未考慮完全的地方,望不吝賜教2023-08-08
這篇文章主要介紹了Mysql中文亂碼問題的最佳解決方法,需要的朋友可以參考下2014-07-07
mysql導(dǎo)入sql文件報(bào)錯(cuò) ERROR 2013 2006 2002
今天在做項(xiàng)目的時(shí)候遇到個(gè)問題，就是往mysql里導(dǎo)入sql文件的時(shí)候總是報(bào)ERROR 2013 2006 2002，研究了一番才找到解決辦法，這里記錄下來分享給大家2014-11-11
MySQL中使用SHOW PROFILE命令分析性能的用法整理
這篇文章主要介紹了MySQL中使用show profile命令分析性能的用法整理,show profiles是數(shù)據(jù)庫性能優(yōu)化的常用命令,需要的朋友可以參考下2015-11-11