Shulou(Shulou.com)06/01 Report--

Walker science and technology Luo Xiaobo

1. Recurrence and simple analysis

2. Reappearance, detailed analysis and verification

2.1. Reappearance and detailed analysis

2.1.1. Stop slave

2.1.2. Change master to master_auto_position=0

2.1.3. Start slave

2.2. Solution verification

3. Summary

Today, our colleague said that we encountered a strange problem, that on MySQL 5.7.18, in the master-slave replication structure, when the slave library used the change master statement to switch master_auto_position=1 to 0, the SQL thread reported an error ([ERROR] Slave SQL for channel'': Error'@ SESSION.GTID_NEXT cannot be set to ANONYMOUS when @ @ GLOBAL.GTID_MODE = ON.'). On query. Default database: 'sbtest'. Query: 'BEGIN', Error_code: 1782), then, in an attempt to fix it, change it to 1, restart replication to normal, and then change to 0 to restart replication. At this time, the data is lost, and after switching over and over again several times, MySQL crash is gone. At that time, my first reaction to this question was to look confused (because the 1782 error is usually an ANONYMOUS transaction error reading from the library IO thread to the main library after replication architecture enabled GTID replication). Then, after being dumbfounded for a while, I thought of some possible causes of the problem. Below, we conduct a dialysis on the causes and consequences of this problem through the three steps of "reappearance and simple analysis", "reappearance, detailed analysis and verification" and "summary". Please follow me.

List hardware configuration, operating system, and database environment information first

Environmental information

Operating system: CentOS Linux release 7.2.1511 (Core)

Sysbench version: sysbench-0.5-3.el6.x86_64

* use sysbench to create 8 tables with 500W data

Percona-toolkit version: percona-toolkit-3.0.3-1.el7.x86_64

Percona-xtrabackup version: percona-xtrabackup-24-2.4.4-1.el7.x86_64

Database version: MySQL 5.7.18

Key parameters of database configuration: * Master library: double one, log_slave_updates,log-bin,binlog_rows_query_log_events=ON,server-id=330614,slave_parallel_type=LOGICAL_CLOCK,enforce_gtid_consistency=ON,gtid_mode=on,innodb_buffer_pool_size=2G* slave library: double one, double TABLE,log_slave_updates,log-bin,binlog_rows_query_log_events=ON,server-id=330615,slave_parallel_type=LOGICAL_CLOCK,enforce_gtid_consistency=ON,gtid_mode=on,innodb_buffer_pool_size=2G Slave_parallel_workers=4 host configuration hardware configuration:

* CPU:4 vcpus* memory: 8G * disk: 50g SSD* Nic: Speed: 100Mb/sIP:

* Master Library: 10.10.20.14 * Slave Library: 10.10.20.15 solemnly declare: this article is for learning and communication only, please do not test in the production environment!

1. Repetition and simple analysis. First of all, we use a number of backups in the master database to build the master-slave replication structure (sysbench creation and master-slave replication steps are omitted), and use master_auto_position=1 to start replication when the slave database is initially built.

The main library is pressurized with the following sysbench statement

Sysbench-test=oltp-db-driver=mysql-mysql-table-engine=innodb-mysql-socket=/home/mysql/data/mysqldata1/sock/mysql.sock-mysql-port=3306-mysql-db=sbtest\

-mysql-user='qbench'-- mysql-password='qbench'-- test=/usr/share/doc/sysbench/tests/db/update_non_index.lua-- oltp-table-size=5000000-- oltp-tables-count=4-- num-threads=8-- max-time=1800\

-- max-requests=0-- report-interval=1 run now, we are going to switch master_auto_position=0 from the library

First, execute the show slave status\ G; statement on the slave library to check the replication status. You can see from the following results that everything is fine.

Admin@localhost: (none) 02:46:49 > show slave status\ G

* * 1. Row *

Slave_IO_State: Waiting for master to send event

.

Master_Log_File: mysql-bin.000036

Read_Master_Log_Pos: 119450512

Relay_Log_File: mysql-relay-bin.000002

Relay_Log_Pos: 9530766

Relay_Master_Log_File: mysql-bin.000036

Slave_IO_Running: Yes

Slave_SQL_Running: Yes

.

Exec_Master_Log_Pos: 101635141

.

Seconds_Behind_Master: 47

Master_SSL_Verify_Server_Cert: No

Last_IO_Errno: 0

Last_IO_Error:

Last_SQL_Errno: 0

Last_SQL_Error:

.

Slave_SQL_Running_State: Waiting for slave workers to process their queues

.

Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-731881

Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710502

Auto_Position: 1

.

1 row in set (0.02 sec) execute master_auto_position=0

Admin@localhost: sbtest 09:02:42 > stop slave

Query OK, 0 rows affected (0.08 sec)

Admin@localhost: sbtest 09:02:45 > change master to master_auto_position=0

Query OK, 0 rows affected (0.06 sec)

Admin@localhost: sbtest 09:02:53 > start slave

Query OK, 0 rows affected (0.03 sec)

Admin@localhost: sbtest 09:02:56 > show slave status\ G

* * 1. Row *

Slave_IO_State: Waiting for master to send event

.

Master_Log_File: mysql-bin.000036

Read_Master_Log_Pos: 125448945

Relay_Log_File: mysql-relay-bin.000002

Relay_Log_Pos: 320

Relay_Master_Log_File: mysql-bin.000036

Slave_IO_Running: Yes

Slave_SQL_Running: No

.

Exec_Master_Log_Pos: 120336889

.

Seconds_Behind_Master: NULL

Master_SSL_Verify_Server_Cert: No

Last_IO_Errno: 0

Last_IO_Error:

Last_SQL_Errno: 1782

Last_SQL_Error: Coordinator stopped because there were error (s) in the worker (s). The most recent failure being: Worker 1 failed executing transaction 'NOT_YET_DETERMINED' at master log\

Mysql-bin.000036, end_log_pos 120336968. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.

.

Last_IO_Error_Timestamp:

Last_SQL_Error_Timestamp: 170708 21:02:56

.

Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947-739082

Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875

Auto_Position: 0

.

1 row in set (0.00 sec) you can see from the above results that the SQL thread reported an error. From the information displayed in the Last_SQL_Error field, we can know that a workers thread reported an error and asked to query the error log or performance_schema.replication_applier_status_by_worker table table (in order to prevent the standby database from falling behind the main database, let's stop sysbench first)

Now, let's query the performance_schema.replication_applier_status_by_worker table table admin@localhost: sbtest 09:02:59 > select * from performance_schema.replication_applier_status_by_worker where LAST_ERROR_MESSAGE! =''\ G

* * 1. Row *

CHANNEL_NAME:

WORKER_ID: 1

THREAD_ID: NULL

SERVICE_STATE: OFF

LAST_SEEN_TRANSACTION:

LAST_ERROR_NUMBER: 1782

LAST_ERROR_MESSAGE: Worker 1 failed executing transaction 'NOT_YET_DETERMINED' at master log mysql-bin.000036, end_log_pos 120336968; Error' @ SESSION.GTID_NEXT\

Cannot be set to ANONYMOUS when @ @ GLOBAL.GTID_MODE = ON.' On query. Default database: 'sbtest'. Query: 'BEGIN'

LAST_ERROR_TIMESTAMP: 2017-07-08 21:02:56

What happened to 1 row in set (0.00 sec)? Only when the gtid_mode parameter of the master database is set to OFF and OFF_PERMISSIVE will the ANONYMOUS transaction be generated and written to the binlog. At this time, the gtid_mode configuration parameter of the master library is absolutely untouched, and the slave database has been working normally in GTID replication mode before performing the above operation. In addition, this error usually occurs when the I / O thread reads the binlog of the master database, and this error is reported for the first time. awkward. Just to be on the safe side, check the value of gtid_mode in the main library.

Admin@localhost: sbtest 08:59:15 > show variables like 'gtid_mode'

+-+ +

| | Variable_name | Value |

+-+ +

| | gtid_mode | ON |

+-+ +

1 row in set (0.01sec) you can see from the above results that the gtid_mode parameter of the main library has not been modified. Since the 1782 error is reported by the SQL thread, let's parse the relay log to find Exec_Master_Log_Pos: 120336889 (where the coordinator thread stops) and 120336968 where the worker thread reports the error (where the error worker thread stops), whether it is an ANONYMOUS transaction (note that this pos is the binlog pos of the main library Pos that is not relay log, cannot use-- start-position option)

'Let 's take a look at the relay log directory first'

[root@luoxiaobo-02 relaylog] # ll

The total dosage is 7092

-rw-r-. 1 mysql mysql 247 July 8 21:02 mysql-relay-bin.000001

-rw-r-. 1 mysql mysql 7253186 July 8 21:03 mysql-relay-bin.000002

-rw-r-. 1 mysql mysql 120 July 8 21:02 mysql-relay-bin.index

'# two were found, parsing the last relay log (the first may not contain data) and redirecting to a file a.sql'

[root@luoxiaobo-02 relaylog] # mysqlbinlog-vv mysql-relay-bin.000002 > a.sql

"# vim open this file and search for 120336968 (here only some of the content we need is intercepted)"

# at 123

# 170708 21:02:56 server id 330615 end_log_pos 154 CRC32 0x6a8ed689 Previous-GTIDs

'# Nani. This is empty.'

# [empty]

# at 154

'# this is the Exec_Master_Log_Pos location when the coordinator thread reports an error. However, due to the use of multithreaded replication, this error location is not necessarily the location where the workers thread actually triggered the error. We need to look up the performance_schema.replication_applier_status_by_worker table'\

The location of the error occurred in the worker thread queried in #, because once a worker thread reports an error, all worker threads will be triggered to terminate and the coordinator thread will be terminated.

# 700101 8:00:00 server id 330614 end_log_pos 0 CRC32 0x122c770b Rotate to mysql-bin.000036 pos: 120336889

# at 201

The event immediately following the location where the coordinator thread stops is the FDE of relay log, indicating that the location where the coordinator thread stops is not the event' of transaction data

# 170708 11:42:56 server id 330614 end_log_pos 0 CRC32 0x9433d36a Start: binlog v 4, server v 5.7.18-log created 170708 11:42:56

.

# at 320

'# this is the location where all worker threads and coordinator threads stop reporting errors. What's wrong here? If you take a closer look, there should be a GTID event recording a GTID number in front of this Query event (when GTID replication is enabled,'\

'# for DML statements, if copied in row format, there is usually a record in the GTID event,EVENT used to record the GTID before the BEGIN statement similar to SET @ @ SESSION.GTID_NEXT=' ec123678-5e26-11e7-9d38-000c295e08a0purpose.'

'# in 5.7A, even if you use the traditional replication mode, there will be a similar content recorded in the GTID event,EVENT: SET @ @ SESSION.GTID_NEXT=' ANONYMOUS 'except that it is now missing!!'

# 170708 21:02:45 server id 330614 end_log_pos 120336968 CRC32 0x5a50ec65 Query thread_id=49 exec_time=0 error_code=0

SET timestamp 1499518965 raceme raceme thread readability idling 49max raceme / session.

SET @ @ session.foreign_key_checks=1, @ @ session.sql_auto_is_null=0, @ @ session.unique_checks=1, @ @ session.

SET @ @ session.sqlhammer modewords 1436549152

SET @ @ session.auto_increment_increment=2, @ @ session.

/ *!\ C latin1 * /! * /

SET @ @ session. Session. Session setting client.session. Session. Collationalization connections8. Session. Session. Collationalization serverationserver83Universe.

SET @ @ session. Session. LCC timetables namespace.

SET @ @ session.collationalization databases

BEGIN

/ *! * /

# at 399

# 170708 21:02:45 server id 330614 end_log_pos 120337151 CRC32 0xfebefb51 Rows_query

# UPDATE sbtest2 SET caterpillar 65170974949-02872074133-35491912643-76037682303-52924518173-58373441038-15151348493-46026501347-34340253549-84073419150' WHERE id=2476460

# at 582

# 170708 21:02:45 server id 330614 end_log_pos 120337210 CRC32 0x6c83af43 Table_map: `sbtest`.`sbtest2` mapped to number 121

# at 641

# 170708 21:02:45 server id 330614 end_log_pos 120337626 CRC32 0xde840c87 Update_rows: table id 121 flags: STMT_END_F

BINLOG can see from the above information that the content of a GTID SET should have been recorded in Previous-GTIDs 's event (similar to: b57c75c2-6205-11e7-8d9f-525400a4b2e1:337711-412882), but now it has become "[empty]". In the following log, Query event should have a GTID event to record GTID SET, but now it is missing! What's going on?

Since the binlog event group of a transaction recorded in relay log has been lost, let's go to the binlog of the main library to parse (parse Relay_Master_Log_File: mysql-bin.000036,). From the following information, we can see the complete events group of the transaction corresponding to 120336968 in the binlog of the main library, where GTID is "b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946".

.

# at 120336824

'# here is the missing GTID EVENT'

# 170708 21:02:45 server id 330614 end_log_pos 120336889 CRC32 0x5d86abf6 GTID last_committed=144511 sequence_number=144517

'# missing GTID number'

SET @ @ SESSION.GTID_NEXT= 'b57c75c2-6205-11e7-8d9fmuri 525400a4b2e1b57c75c2 732946 /

# at 120336889

# 170708 21:02:45 server id 330614 end_log_pos 120336968 CRC32 0x5a50ec65 Query thread_id=49 exec_time=0 error_code=0

SET timestamp 1499518965

BEGIN

/ *! * /

# at 120336968

# 170708 21:02:45 server id 330614 end_log_pos 120337151 CRC32 0xfebefb51 Rows_query

# UPDATE sbtest2 SET caterpillar 65170974949-02872074133-35491912643-76037682303-52924518173-58373441038-15151348493-46026501347-34340253549-84073419150' WHERE id=2476460

# at 120337151

# 170708 21:02:45 server id 330614 end_log_pos 120337210 CRC32 0x6c83af43 Table_map: `sbtest`.`sbtest2` mapped to number 121

# at 120337210

# 170708 21:02:45 server id 330614 end_log_pos 120337626 CRC32 0xde840c87 Update_rows: table id 121 flags: STMT_END_F

BINLOG calmly analyzes why the relay log from the library is missing. Wait, wait, wait. After looking back at the show slave status information before and after performing the operation, we find that the differences in GTID-related information after stop slave;change master to master_auto_position=0;start slave; are as follows:

'# before switching:'

Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-731881

Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710502

'# after switching:'

Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947-739082

Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875

"# take a look at the show master status information from the library again"

Admin@localhost: sbtest 09:05:36 > show master status

+-- +

| | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set | |

+-- +

| | mysql-bin.000001 | 9717837 | b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875 |

+-- +

1 row in set (0.00 sec) has a problem! I just operate stop slave;change master to master_auto_position=0;start slave;, but now there is something strange in the information we can see: the values of Retrieved_Gtid_Set in the two show slave status outputs do not overlap at all, the former GTID transaction number is 699054-731881, and the latter is 732947-739082.

The smallest GTID in Retrieved_Gtid_Set is 22072 transaction numbers larger than the largest GTID in Executed_Gtid_Set.

By looking at the relay log of the slave library, the transaction number of the GTID transaction in which the error is reported is b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946, which happens to be the Retrieved_Gtid_Set starting value of the show slave status when the error is reported after + 1, that is to say: because the GTID EVENT of this transaction (732946) is missing, and because the Previous-GTIDs event record of the GTID SET is [empty] when the relay log is switched, the final starting value of Retrieved_Gtid_Set is calculated from the next transaction. That is, b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947 begins to calculate, where is the missing log?

Let's parse the mysql-relay-bin.000001 and you can see from the following results that there is no data-related content in this relay log. Where's the lost journal?

[root@luoxiaobo-02 relaylog] # mysqlbinlog-vv mysql-relay-bin.000001

Mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'

/ *! 50530 SET @ @ SESSION.PSEUDO_SLAVE_MODE=1*/

/ *! 50003 SET @ OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/

DELIMITER / *! * /

# at 4

# 170708 21:02:53 server id 330615 end_log_pos 123 CRC32 0xc16fd9be Start: binlog v 4, server v 5.7.18-log created 170708 21:02:53 at startup

# This Format_description_event appears in a relay log and was generated by the slave thread.

# at 123

# 170708 21:02:53 server id 330615 end_log_pos 194 CRC32 0xd425b7a8 Previous-GTIDs

# b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-732945

# at 194

# 170708 21:02:56 server id 330615 end_log_pos 247 CRC32 0x43311780 Rotate to mysql-relay-bin.000002 pos: 4

SET @ @ SESSION.GTID_NEXT= 'AUTOMATIC' / * added by mysqlbinlog * /! * /

DELIMITER

# End of log file

/ *! 50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/

/ *! 50530 SET @ @ SESSION.PSEUDO_SLAVE_MODE=0*/ analysis so far, there seems to be no way out. Wait, wait, What the mysql server backend will do is worth the effort. The key instructions are as follows, to the effect that the change master to master_auto_position=0 statement can be used when switching to a file-based replication protocol in GTID-based replication mode, and the MASTER_LOG_FILE and MASTER_LOG_POS options should be specified. (it has been verified that if the MASTER_LOG_FILE and MASTER_LOG_POS options are not specified, the change master statement is executed Then the SQL thread location is based on the IO thread location, and if the MASTER_LOG_FILE and MASTER_LOG_POS options are specified, the IO thread location is based on the SQL thread location.), after version 5.7.4, use change master to. Statement, if both the IO and SQL threads are stopped, all relay log files will be deleted unless you specify both the RELAY_LOG_FILE and RELAY_LOG_POS options (it has been verified that all current relay log will be deleted as long as the RELAY_LOG_FILE and RELAY_LOG_POS options are not specified, no matter how the other options are specified):

That is to say, when we use the change master statement, using only the master_auto_position option without specifying the MASTER_LOG_FILE and MASTER_LOG_POS options is itself a non-standard behavior, coupled with not specifying the RELAY_LOG_FILE and RELAY_LOG_POS options, causing the relay log to be cleaned up, and we know that executing stop slave earlier Statement, we can see that there is also replication delay (Seconds_Behind_Master: 47), that is, the cleaning of this part of the replication delay relay log may be the cause of the worker thread error (the missing GTID EVENT is recorded in the cleaned relay log)

Now, we should find the reason, but we need further confirmation, but according to the current crime scene, the investigation can no longer be carried out, and we need to restore the copy first. reproduce and view as comprehensive information as possible at each step for diagnosis.

To restore the replication environment, we can set master_auto_position to 1. According to the GTID replication protocol, when setting to 1 to start replication, the IO thread will automatically calculate the GTID SET of requesting binlog from the master database according to the formula "UNION (@ global.gtid_executed, Retrieved_gtid_set-last_received_GTID)", telling the master database what transactions it has currently performed, and the master database will send the transactions missing from the slave database to the slave database. So in theory, you only need to set master_auto_position to 1 to start replication to return to normal.

Admin@localhost: sbtest 09:52:41 > stop slave

Query OK, 0 rows affected (0.00 sec)

Admin@localhost: sbtest 09:52:47 > change master to master_auto_position=1

Query OK, 0 rows affected (0.02 sec)

Admin@localhost: sbtest 09:53:01 > start slave

Query OK, 0 rows affected (0.02 sec)

Admin@localhost: sbtest 09:53:11 > show slave status\ G

* * 1. Row *

Slave_IO_State: Waiting for master to send event

.

Master_Log_File: mysql-bin.000036

Read_Master_Log_Pos: 127589755

Relay_Log_File: mysql-relay-bin.000002

Relay_Log_Pos: 849241

Relay_Master_Log_File: mysql-bin.000036

Slave_IO_Running: Yes

Slave_SQL_Running: Yes

.

Exec_Master_Log_Pos: 102801341

.

Seconds_Behind_Master: 3075

Master_SSL_Verify_Server_Cert: No

Last_IO_Errno: 0

Last_IO_Error:

Last_SQL_Errno: 0

Last_SQL_Error:

.

Last_IO_Error_Timestamp:

Last_SQL_Error_Timestamp:

.

Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:710876-741652

Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-711894

Auto_Position: 1

...

1 row in set (0.01 sec)

From the above results, we can see that the replication of the slave library is back to normal. Now, all we need to do is wait for the SQL thread of the slave library to catch up with the IO thread, and then use the pt tool to do a master-slave data check. From the following results, we can see that the test library sbtest has the same data in the master-slave library. There is no difference [root@luoxiaobo-01] # pt-table-checksum-- nocheck-replication-filters-- no-check-binlog-format-- replicate=xiaoboluo.checksums-- databases sbtest hype localhost journal upright admin dint pamphletsg0meme 3306

Checksumming sbtest.sbtest1: 57% 00:24 remain

TS ERRORS DIFFS ROWS CHUNKS SKIPPED TIME TABLE

07-08T22:19:10 00 5007738 28 0 59.849 sbtest.sbtest1

Checksumming sbtest.sbtest2: 49% 00:30 remain

Checksumming sbtest.sbtest2: 97% 00:01 remain

07-08T22:20:17 00 5007905 27 0 67.127 sbtest.sbtest2

Checksumming sbtest.sbtest3: 52% 00:27 remain

07-08T22:21:23 00 5007858 28 0 65.440 sbtest.sbtest3

Checksumming sbtest.sbtest4: 48% 00:32 remain

Checksumming sbtest.sbtest4: 92% 00:04 remain

07-08T22:22:35 00 5007914 29 0 71.766 sbtest.sbtest4

Checksumming sbtest.sbtest5: 61% 00:19 remain

07-08T22:23:38 00 5007412 29 0 63.463 sbtest.sbtest5

Checksumming sbtest.sbtest6: 58% 00:21 remain

07-08T22:24:38 00 5007473 29 0 59.838 sbtest.sbtest6

Checksumming sbtest.sbtest7: 53% 00:27 remain

07-08T22:25:44 00 5007216 29 0 66.526 sbtest.sbtest7

Checksumming sbtest.sbtest8: 50% 00:29 remain

07-08T22:26:47 00 5007273 28 0 62.753 sbtest.sbtest8

'# if DIFFS lists the existing non-zero value, it means that the master and backup data are inconsistent. You can execute the following statement to perform synchronization, and then perform the pt-table-checksum check again until the DIFFS column does not have a 0 value.

Pt-table-sync-- replicate=xiaoboluo.checksums-- databases sbtest hobbies localhostthecontrol adminthecominetsg0reignedPrun3306-- Why does execute have a minus last_received_GTID in its formula? According to the official documentation, last_received_GTID will not be subtracted before version 5.7.5, but last_received_GTID will be subtracted after 5.7.5 because. When the IO thread is continuously reading the main library binlog, it is read in event units, and a transaction contains an event group, so suddenly performing stop slave or other abnormal behavior may cause a transaction to read only part of the event. If you do not subtract the binlog reading incomplete GTID, it may cause SQL thread replication error termination. The following picture shows the official explanation of this formula:

Now, let's reproduce the steps.

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.