错误环境:
OS: CentOS release 6.5 (Final)
MySQL: MySQL 5.7.19
主从参数配置:
master_info_repository = TABLE relay_log_info_repository = TABLE gtid_mode = on enforce-gtid-consistency = true log_slave_updates = 1 slave-parallel-workers = 8 slave-parallel-type = LOGICAL_CLOCK slave_preserve_commit_order = 0
错误描述:
从库SQL进程异常停止(从库在此前刚因内存异常重启),报错内容为:
Last_Errno: 1782 Last_Error: Error executing row event: '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.'
出库执行位点:
Relay_Master_Log_File: mysql-bin.001204 Exec_Master_Log_Pos: 52454628 Executed_Gtid_Set: 6b5be2cf-b1ad-11e7-aeb2-246e965aa709:1432389-825991260
按照位点信息去主库上解析binlog
/export/servers/mysql/bin/mysqlbinlog -vvv /export/data/mysql/data/mysql-bin.001204 --start_position=52454628 |more
输出内容为:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #190518 1:05:08 server id 60863 end_log_pos 123 CRC32 0x0545d99b Start: binlog v 4, server v 5.7.19-log created 190518 1:05:08 BINLOG ' xOneXA+/7QAAdwAAAHsAAAAAAAQANS43LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA AZvZRQU= '/*!*/; # at 52454628 #190518 2:56:10 server id 60863 end_log_pos 52455702 CRC32 0x24c5219e Update_rows: table id 27578 flags: STMT_END_F BINLOG ' ygPfXB+/7QAAMgQAABZpIAMAALprAAAAAAEAAgBX/////////////////////////////6ABAyBw D8B8ALyAPfUdAAAAAAABMQwxMDAwMDAwMTc1NTmMAOWuieWwlOmbhSBBTkVSWUEg5pel5byP5ZWG 6LaF5ZCM5qy+IOaHkuS6uuaymeWPkeixhuiii+aXoOWNsOWIm+aEj+aRh+aRh+akheS8kemXsuWM l+asp+amu+amu+exs+WNleS6uuWkmuWKn+iDveW4g+iJuuaymeWPkSDnj4rnkZrok50g5aSn5qy+ ATCAAAAABROIATABMAQAaHpyegYxMzQxNzAJAOa1meaxn+ecgQExATABMAEwATABMAEwBDk4NzAB MAwAMTAwMDAwMDE3NTU5ATABMACZogdLxFzbUkQDMzAxEWdvb2RzSW5mb0Rvd25sb2FkEWdvb2Rz SW5mb0Rvd25sb2FkDAAxMDAwMDAwMTc1NTmAAAAAAAAAATABMAEwATCAAAAAAAAAATCAAAAAAAAA gAAAAAAAAIAAAAAAAACAAAAAAAAAgAAAAAAAAAEwAzY1MQEzAIAAAAKeAACAAAACXQAAgAAAAlgA AAEwATABMAABMD4AamZzL3QzMDM4Mi8yMzgvMjIwMzM3MzU1LzI4MzAzMi8zNjJjODZiNy81YmVi YjI5N05lMWE5MjZmYy5qcGcBADElzoqzagEAAAPnrrEAAIAAAAAAAACAAAAAAAAAoAEDIHAPwHwA vIA99R0AAAAAAAExDDEwMDAwMDAxNzU1OYwA5a6J5bCU6ZuFIEFORVJZQSDml6XlvI/llYbotoXl kIzmrL4g5oeS5Lq65rKZ5Y+R6LGG6KKL5peg5Y2w5Yib5oSP5pGH5pGH5qSF5LyR6Zey5YyX5qyn 5qa75qa757Gz5Y2V5Lq65aSa5Yqf6IO95biD6Im65rKZ5Y+RIOePiueRmuiTnSDlpKfmrL4BMIAA AAAFE4gBMAEwBABoenJ6BjEzNDE3MAkA5rWZ5rGf55yBATEBMAEwATABMAEwATAEOTg3MAEwDAAx MDAwMDAwMTc1NTkBMAEwAJmiB0vEXN8DygMzMDERZ29vZHNJbmZvRG93bmxvYWQRZ29vZHNJbmZv RG93bmxvYWQMADEwMDAwMDAxNzU1OYAAAAAAAAABMAEwATABMIAAAAAAAAABMIAAAAAAAACAAAAA AAAAgAAAAAAAAIAAAAAAAACAAAAAAAAAATADNjUxATMAgAAAAp4AAIAAAAJdAACAAAACWAAAATAB MAEwAAEwPgBqZnMvdDMwMzgyLzIzOC8yMjAzMzczNTUvMjgzMDMyLzM2MmM4NmI3LzViZWJiMjk3 TmUxYTkyNmZjLmpwZwEAMSOx2cNqAQAAA+eusQAAgAAAAAAAAIAAAAAAAACeIcUk '/*!*/; ### Row event for unknown table #27578# at 52455702 #190518 2:56:10 server id 60863 end_log_pos 52455733 CRC32 0xb829837d Xid = 8647697161 COMMIT/*!*/; # at 52455733 #190518 2:56:10 server id 60863 end_log_pos 52455798 CRC32 0x02c73826 GTID last_committed=21489 sequence_number=21490 -rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990109'/*!*/; # at 52455798 #190518 2:56:10 server id 60863 end_log_pos 52455871 CRC32 0x1863b7ae Query thread_id=7254910 exec_time=0 error_c ode=0 SET TIMESTAMP=1558119370/*!*/; SET @@session.pseudo_thread_id=7254910/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1411383296/*!*/; 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=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 52455871
网上关于错误“Row event for unknown table”的资料较少,查到资料解释大意是在建立table map信息丢失导致。
参考链接:
https://bugs.mysql.com/bug.php?id=60964
https://www.jianshu.com/p/4e28f09b3ce5
从上面的解析结果发现,该事务设置GTID_NEXT,难道真的是匿名事务?
通过指定时间段方式来解析:
/export/servers/mysql/bin/mysqlbinlog -vvv /export/data/mysql/data/mysql-bin.001204 --start_datetime='2019-05-18 2:56:09' --stop_datetime='2019-05-18 2:56:11'
解析结果包含如下信息:
# at 52454142 #190518 2:56:10 server id 60863 end_log_pos 52454173 CRC32 0xb0e1832b Xid = 8647697160 COMMIT/*!*/; ### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990107的事务提交 # at 52454173 #190518 2:56:10 server id 60863 end_log_pos 52454238 CRC32 0x83d1552a GTID last_committed=21486 sequence_number=21489 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; ### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108的事务开始 SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108'/*!*/; # at 52454238 #190518 2:56:10 server id 60863 end_log_pos 52454314 CRC32 0xb78b3241 Query thread_id=7172612 exec_time=0 error_code=0 SET TIMESTAMP=1558119370/*!*/; BEGIN /*!*/; # at 52454314 #190518 2:56:10 server id 60863 end_log_pos 52454628 CRC32 0x643ab683 Table_map: `report`.`bs_itembase` mapped to number 27578 # at 52454628 #190518 2:56:10 server id 60863 end_log_pos 52455702 CRC32 0x24c5219e Update_rows: table id 27578 flags: STMT_END_F BINLOG ' ygPfXBO/7QAAOgEAAORkIAMAALprAAAAAAEABnJlcG9ydAALYnNfaXRlbWJhc2UAVwgPDw8PD/b2 Dw8PDw8PDw8PDw8PDw8PDw8PDw8PDxIRDw8PDw8PD/YPDw8PDw8PD/YP9vb29g8P9g8PDw8PDw8P Afb29g8PDwEPDw8PDw8PDwgPARD29qKWAFoA3AUDAB4ADwQPBB4AAwCWACwBlgAAAwMAAwAeAB4A AwADAAMAAwADAJYAAwBYAgMAAwCWAAADAAB4ADwAPABYAgMAAwB4AA8EeAB4AHgAeAADAAMAAwAD AA8EAwAPBA8EDwQPBB4AHgAPBAMAAwADAB4AHgAeADwAPAAPBA8EDwQDAAMAAwADAHgA3AVYAiwB WALcBVgCPAABAA8EDwT+//8/////////H4O2OmQ= ygPfXB+/7QAAMgQAABZpIAMAALprAAAAAAEAAgBX/////////////////////////////6ABAyBw D8B8ALyAPfUdAAAAAAABMQwxMDAwMDAwMTc1NTmMAOWuieWwlOmbhSBBTkVSWUEg5pel5byP5ZWG 6LaF5ZCM5qy+IOaHkuS6uuaymeWPkeixhuiii+aXoOWNsOWIm+aEj+aRh+aRh+akheS8kemXsuWM l+asp+amu+amu+exs+WNleS6uuWkmuWKn+iDveW4g+iJuuaymeWPkSDnj4rnkZrok50g5aSn5qy+ ATCAAAAABROIATABMAQAaHpyegYxMzQxNzAJAOa1meaxn+ecgQExATABMAEwATABMAEwBDk4NzAB MAwAMTAwMDAwMDE3NTU5ATABMACZogdLxFzbUkQDMzAxEWdvb2RzSW5mb0Rvd25sb2FkEWdvb2Rz SW5mb0Rvd25sb2FkDAAxMDAwMDAwMTc1NTmAAAAAAAAAATABMAEwATCAAAAAAAAAATCAAAAAAAAA gAAAAAAAAIAAAAAAAACAAAAAAAAAgAAAAAAAAAEwAzY1MQEzAIAAAAKeAACAAAACXQAAgAAAAlgA AAEwATABMAABMD4AamZzL3QzMDM4Mi8yMzgvMjIwMzM3MzU1LzI4MzAzMi8zNjJjODZiNy81YmVi YjI5N05lMWE5MjZmYy5qcGcBADElzoqzagEAAAPnrrEAAIAAAAAAAACAAAAAAAAAoAEDIHAPwHwA vIA99R0AAAAAAAExDDEwMDAwMDAxNzU1OYwA5a6J5bCU6ZuFIEFORVJZQSDml6XlvI/llYbotoXl kIzmrL4g5oeS5Lq65rKZ5Y+R6LGG6KKL5peg5Y2w5Yib5oSP5pGH5pGH5qSF5LyR6Zey5YyX5qyn 5qa75qa757Gz5Y2V5Lq65aSa5Yqf6IO95biD6Im65rKZ5Y+RIOePiueRmuiTnSDlpKfmrL4BMIAA AAAFE4gBMAEwBABoenJ6BjEzNDE3MAkA5rWZ5rGf55yBATEBMAEwATABMAEwATAEOTg3MAEwDAAx MDAwMDAwMTc1NTkBMAEwAJmiB0vEXN8DygMzMDERZ29vZHNJbmZvRG93bmxvYWQRZ29vZHNJbmZv RG93bmxvYWQMADEwMDAwMDAxNzU1OYAAAAAAAAABMAEwATABMIAAAAAAAAABMIAAAAAAAACAAAAA AAAAgAAAAAAAAIAAAAAAAACAAAAAAAAAATADNjUxATMAgAAAAp4AAIAAAAJdAACAAAACWAAAATAB MAEwAAEwPgBqZnMvdDMwMzgyLzIzOC8yMjAzMzczNTUvMjgzMDMyLzM2MmM4NmI3LzViZWJiMjk3 TmUxYTkyNmZjLmpwZwEAMSOx2cNqAQAAA+eusQAAgAAAAAAAAIAAAAAAAACeIcUk '/*!*/; ### UPDATE `report`.`xxxx` ### WHERE ### 更新语句... # at 52455702 #190518 2:56:10 server id 60863 end_log_pos 52455733 CRC32 0xb829837d Xid = 8647697161 COMMIT/*!*/; ### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108的事务提交 # at 52455733 #190518 2:56:10 server id 60863 end_log_pos 52455798 CRC32 0x02c73826 GTID last_committed=21489 sequence_number=21490 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; ### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990109的事务开始 SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990109'/*!*/; # at 52455798 #190518 2:56:10 server id 60863 end_log_pos 52455871 CRC32 0x1863b7ae Query thread_id=7254910 exec_time=0 error_code=0 SET TIMESTAMP=1558119370/*!*/; SET @@session.sql_mode=1411383296/*!*/; BEGIN /*!*/; # at 52455871 #190518 2:56:10 server id 60863 end_log_pos 52455941 CRC32 0xb9e2e221 Table_map: `dcomb`.`snapshot_position` mapped to number 30731 # at 52455941 #190518 2:56:10 server id 60863 end_log_pos 52456099 CRC32 0xea181383 Update_rows: table id 30731 flags: STMT_END_F
从上面解析内容可以发现事务中包含有GTID信息,但由于从库复制使用基于位点方式搭建,且从库开启多线程复制,因此Exec_Master_Log_Pos=52454628信息记录并不准确,而从该位置点开始应用BINLOG,没有执行该位点上面的内容(标黄部分):
#190518 2:56:10 server id 60863 end_log_pos 52454238 CRC32 0x83d1552a GTID last_committed=21486 sequence_number=21489 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108的事务开始
SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108'/*!*/;
# at 52454238
#190518 2:56:10 server id 60863 end_log_pos 52454314 CRC32 0xb78b3241 Query thread_id=7172612 exec_time=0 error_code=0
SET TIMESTAMP=1558119370/*!*/;
BEGIN
/*!*/;
# at 52454314
#190518 2:56:10 server id 60863 end_log_pos 52454628 CRC32 0x643ab683 Table_map: `report`.`bs_itembase` mapped to number 27578
# at 52454628
#190518 2:56:10 server id 60863 end_log_pos 52455702 CRC32 0x24c5219e Update_rows: table id 27578 flags: STMT_END_F
当执行到COMMIT时,由于没有设置GTID_NEXT,因此MySQL认为该事务未匿名事务,SQL线程异常停止。
上面的情况是跳过"SET @@SESSION.GTID_NEXT" 和"BEGIN"两部分,而如果只跳过"SET @@SESSION.GTID_NEXT",则执行BEGIN时,会报如下错误:
Last_Errno: 1782 Last_Error: Error '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: ''. Query: 'BEGIN'
位于该错误位点的GTID为“6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108”,而从库执行过的GTID为“6b5be2cf-b1ad-11e7-aeb2-246e965aa709:1432389-825991260”,由于缺少GTID_NEXT标识事务,从库无法判定该事务是否已在从库上执行,也就无法自动跳过该事务。
由于参数relay_log_recovery默认值为OFF,从库服务器上未明确设置参数relay_log_recovery=ON,还需验证该参数对上述异常的影响,未完待续。