Shulou(Shulou.com)05/31 Report--

This article is about the example analysis of master-slave exceptions caused by manually registering binlog files. The editor thinks it is very practical, so share it with you as a reference and follow the editor to have a look.

I. the source of the problem

A friend @ Shuimitian asked me, based on POSITION master and follower. He did the following

Some backed up binlog files are added to the directory

Modify the index files to add these binlog files

Flush binary logs

Then there is a lot of delay in the whole master-slave environment.

Second, the test of friends

Here is the test of another friend @ Xu Chenliang:

On 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 | 11735 | mysql-binlog.000039 | mysql-binlog.000040 | mysql-binlog.000041 | mysql-binlog.000041 | 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) execute insert data (root:db1@xucl:10:31:23) [xucl] > insert into t values (9 sec) | Copy the backed-up binlog back to the original directory and modify the index file to register [root@izbp12nspj47ypto9t6vyez logs] # ll Total usage 884 ll RWWhat r-1 mysql mysql 1019 May 20 22:03 mysql-binlog.000031-rw-r- 1 mysql mysql 424 May 20 22:03 mysql-binlog.000032-rw-r- 1 mysql mysql 244 May 20 22:03 mysql-binlog.000033-rw-r -- 1 mysql mysql 2332 May 20 22:03 mysql-binlog.000034-rw-r- 1 mysql mysql 2134 May 20 22:03 mysql-binlog.000035-rw-r- 1 mysql mysql 845915 May 20 22:03 mysql-binlog.000036-rw-r- 1 mysql mysql 11735 May 20 22:05 mysql-binlog.000037-rw-r- 1 mysql mysql 284 May 20 22:06 mysql-binlog. 000038 mysql mysql r-1 mysql mysql 284 May 21 10:28 mysql-binlog.000039-rw-r- 1 mysql mysql 284 May 21 10:28 mysql-binlog.000040-rw-r- 1 mysql mysql 284 May 21 10:28 mysql-binlog.000041-rw-r- 1 mysql mysql 491 May 21 10:31 mysql-binlog.000042-rw-r- 1 mysql mysql 2045 June 21 10:30 mysql-binlog.index main library flush binary logs (root:db1@xucl:10:32:51) [(none)] > flush binary logs Query OK, 0 rows affected (0.01sec) (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 | mysql-binlog.000039 | mysql-binlog.000039 | mysql-binlog.000040 | 284 | mysql-binlog.000041 | mysql-binlog.000042 | 541 | mysql-binlog.000043 | 234 | +-| +-+ 13 rows in set (0.00 sec) at this time The error in slave is as follows: (root:db1@xucl:10:31:05) [(none)] > show slave status\ row * 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: NULLMaster_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) judging from the error report on slave After the master library flush binary logs, the slave library reads the registered binlog and apply the third, phenomenon description

From the perspective of the entire test, MySQL depends on the transfer and application of manually registered files. The error is reported because the library used to be GITD_MODE=ON, but during the test, GTID_MODE has been turned off and changed to POSITION mode. This error is because the DUMP thread detects:

Image.png

This picture is from a new series I wrote (it hasn't been released yet, and it won't be ready until the end of the year). Anyway, the DUMP thread is already starting to transfer old binlog files. So what's the reason? We will explain below.

4. The operation of flush binary logs to binlog

The flush binary logs will contain the following actions:

Get the new binlog file name

Turn off the old binlog

Close index file

Open index file

Open a new binlog

Add a new binlog to indexfile

For more information, please see the function MYSQL_BIN_LOG::new_file_impl. Note that getting the new binlog file name is achieved through the function find_uniq_filename, which contains the following code:

File_info= dir_info- > dir_entry; for (I = dir_info- > number_off_files; iMurray -; 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

Scan the binlog file in the index file file to get the one with the highest serial number, and then add 1. The stack frames are as follows:

# 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

So even if we modify index file,flush binary logs manually, it won't be a problem, because it actually scans the index file file.

At the same time, we also see that flush binary logs reloads index file, when the manually modified index file takes effect, and you can view the files you added using show binary logs.

V. the emergence of the problem of master and slave

After the binlog switch, the DUMP thread also needs to read the next binlog file. Let's see how it confirms which file to read.

The code that loops through each binlog file can be found in the function sender.run (). The following sentence is to find the next binlog file:

Int error= mysql_bin_log.find_next_log (& m_linfo, 0)

The code contained in mysql_bin_log.find_next_log is:

My_b_seek (& index_file, linfo- > index_file_offset); / / offset linfo- > index_file_start_offset= linfo- > index_file_offset; length=my_b_gets (& index_file, fname, FN_REFLEN); / / read file name. If (normalize_binlog_name (full_fname, fname, is_relay_log)) Linfo- > index_file_offset= my_b_tell (& index_file); / / offset from the new record for next use

We can see that the DUMP thread does not actually scan the entire index file, but reads it through the offset of an index file. If you modify the index file manually, the offset will be out of order. So the next file sent by DUMP will be indeterminate. As a result, a manually registered binlog file is sent to the slave library, in which case the following may occur:

If GTID_MODE is turned off and POSITION is used, then this situation must report an error, such as duplicate lines.

If it is GTID_MODE and AUTO_POSITION=1, then the DUMP thread filters the GTID and does not send, because the Event does not send, so the delay will last for a period of 0.

If it is GTID_MODE and AUTO_POSITION=0, then the SQL thread will filter when it applies GITD_EVENT, and the latency may be very large.

Although GTID may be able to shield this problem, the DUMP thread is already considering sending old binlog files, which is inappropriate.

6. Purge binary logs can maintain this offset.

Why is there no problem with purge binary logs, because under the purge binary logs statement, the offset is maintained as follows:

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)

Fatal = (linfo- > index_file_offset! = 0); else linfo- > index_file_offset-= masked purgeworthy offset;} mysql_mutex_unlock (& thd- > LOCK_thd_data)

We can see a statement like linfo- > index_file_offset-= masked purgeworthy off set;. Here are the stack frames:

# 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 (_ _ first=0x3003358, _ _ last=0x3003368, _ _ fags...) 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: 31277, error report in test POSITION mode 1, environment mysql > show binary logs +-+-+ | Log_name | File_size | +-+-+ | binlog.000001 | 198 | binlog.000002 | binlog.000002 | +-+-+ 2 rows in set (0.00 sec) mysql > show create table testcp\ G * * 1. Row * * Table: testcpCreate Table: CREATE TABLE `testcp` (`id` int (11) NOT NULL, PRIMARY KEY (`id`)) ENGINE=InnoDB DEFAULT CHARSET=utf81 row in set (0.00 sec) ERROR: No query specified2, execute a statement

Main library:

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)

From the library:

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

At this point, the DUMP thread index file offset pointer is as follows:

Image.png

3. The main library executes purge binary logs

Copy the original binlog.000001 to binlog.000001bak before doing it, because you have to copy it back later.

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)

Because the purge binary logs command maintains the offset pointer, the index file offset pointer for the DUMP thread is as follows:

Image.png

4. Change manually

Copy binlog.000001bak to binlog.000001, then modify index file to add binlog.000001 back in, and then flush binary logs as follows:

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)

Doing this manually does not maintain the index file offset pointer for the DUMP thread, so it is as follows:

Image.png

In this way, the DUMP thread re-sends the contents of binlog.000002, and the slave library of POSITION can only report an error as follows:

Mysql > select * from replication_applier_status_by_worker\ gateway * 1. Row * * CHANNEL_NAME: WORKER_ID: 1 THREAD_ID: NULL SERVICE_STATE: OFFLAST_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 386LAST_ERROR_TIMESTAMP: 2019-05-21 14:46:26 Thank you for reading! On the "manual registration of binlog files caused by master-slave exception example analysis" this article is shared here, I hope the above content can be of some help to you, so that you can learn more knowledge, if you think the article is good, you can share it out for more people to see it!

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.