GreatSQL社区

搜索

[已解决] 求助:oracle mysql社区版binlog日志反复rollback,导致主从同步...

1994 12 2023-7-10 17:31


这个分布式事务是7月9号 02:59启动的

事务prepare之后没有立即提交

过了11个多小时后(期间业务程序可能经过了宕机重启),binlog中出现了反复rollback该事务的信息,导致主从同步异常,从库抛出Last_SQL_Error: Error 'XAER_NOTA: Unknown XID' on query.

ps:我自己测试时反复rollback事务失败,binlog中也没有记录。业务程序是用的org.springframework.transaction.jta.JtaTransactionManager + com.atomikos.icatch.jta.UserTransactionManager 管理事务。

想请教binlog中这种反复rollback同一事务现象是怎么出现的?
全部回复(12)
数据搬运工 2023-7-10 17:35:37
mysql版本:5.7.37
数据搬运工 2023-7-11 10:59:14
yejr 发表于 2023-7-11 10:43
正常不会出现XA情况,猜测是你的开发框架里玩脱了,或者没用对,所以才产生了这些XA ROLLBACK事务 ...

嗯,作为dba我也怀疑开发用的事务管理组件有问题;另外因为项目是微服务架构,所以统一用了分布式事务xa;想求助的是mysql的binlog日志为何会记录反复单独的rollback事件,手工测试时发现rollback失败,且不会记录binlog,这是我很疑惑的地方。
数据搬运工 2023-7-11 18:01:55
yejr 发表于 2023-7-11 15:11
XA事务是需要和其他应用协同的,别人rollback了,你也得跟着做 :)

叶老师,我做个一个分布式事务测试,你看看:
第一步:开启一个分布式事务,执行到prepare状态。
mysql> select * from t;
+----+------+
| id | name |
+----+------+
|  1 | aaa  |
|  2 | bbb  |
|  3 | cdc  |
|  4 | ddd  |
+----+------+
4 rows in set (0.00 sec)

mysql> XA start  'test002';
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t values(5,'fff');
Query OK, 1 row affected (0.01 sec)

mysql> delete from  t where id=5;
Query OK, 1 row affected (0.00 sec)

mysql> XA END 'test002';
Query OK, 0 rows affected (0.00 sec)

mysql> xa prepare 'test002';
Query OK, 0 rows affected (0.00 sec)

mysql>
mysql> quit
Bye
[root@kmt_mysql_106 ~]#

第二步:过一段时间后(约1小时),重连mysql回滚事务

mysql>
mysql>
mysql> xa rollback 'test002';
Query OK, 0 rows affected (0.01 sec)

mysql> xa rollback 'test002';
ERROR 1397 (XAE04): XAER_NOTA: Unknown XID
mysql> xa rollback 'test002';
ERROR 1397 (XAE04): XAER_NOTA: Unknown XID
mysql> xa rollback 'test002';
ERROR 1397 (XAE04): XAER_NOTA: Unknown XID
mysql> xa rollback 'test002';
ERROR 1397 (XAE04): XAER_NOTA: Unknown XID
发现第一次是可以正常回滚的,后面反复执行会报错

解析binlog日志记录如下:
# at 1433
#230711 16:07:15 server id 7002  end_log_pos 1534 CRC32 0x539c7ee1      Query   thread_id=716   exec_time=0     error_code=0
SET TIMESTAMP=1689062835/*!*/;
XA START X'74657374303032',X'',1
/*!*/;
# at 1534
#230711 16:07:15 server id 7002  end_log_pos 1583 CRC32 0xecc19bf9      Table_map: `testdb`.`t` mapped to number 3086
# at 1583
#230711 16:07:15 server id 7002  end_log_pos 1627 CRC32 0x5e30aea4      Write_rows: table id 3086 flags: STMT_END_F
### INSERT INTO `testdb`.`t`
### SET
###   @1=5
###   @2='fff'
# at 1627
#230711 16:07:45 server id 7002  end_log_pos 1676 CRC32 0xfd51a4a1      Table_map: `testdb`.`t` mapped to number 3086
# at 1676
#230711 16:07:45 server id 7002  end_log_pos 1720 CRC32 0xfe33e8cc      Delete_rows: table id 3086 flags: STMT_END_F
### DELETE FROM `testdb`.`t`
### WHERE
###   @1=5
###   @2='fff'
# at 1720
#230711 16:08:02 server id 7002  end_log_pos 1819 CRC32 0xbd188570      Query   thread_id=716   exec_time=0     error_code=0
SET TIMESTAMP=1689062882/*!*/;
XA END X'74657374303032',X'',1
/*!*/;
# at 1819
#230711 16:08:02 server id 7002  end_log_pos 1862 CRC32 0xa5937a30      XA PREPARE X'74657374303032',X'',1
XA PREPARE X'74657374303032',X'',1
/*!*/;
# at 1862
#230711 17:48:41 server id 7002  end_log_pos 1927 CRC32 0xbd5f80df      GTID    last_committed=5        sequence_number=6       rbr_only=no
SET @@SESSION.GTID_NEXT= '4c6fe017-85bf-11ed-bffe-0050569b5493:5418900'/*!*/;
# at 1927
#230711 17:48:41 server id 7002  end_log_pos 2025 CRC32 0x3f221bd9      Query   thread_id=718   exec_time=0     error_code=0
SET TIMESTAMP=1689068921/*!*/;
XA ROLLBACK X'74657374303032',X'',1
/*!*/;
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*/;

binlog日志中有对应时间的prepare和rollback记录,没有反复rollback的记录,我想这应该是mysql分布式事务xa设计的正常流程。
现在遇到的问题是binlog中出现了反复冗余的rollback记录,我不知道是怎么来的?
1、如果rollback成功了,后续rollback应当执行失败,不会出现在binlog中;
2、如果rollback执行都失败了,那binlog中应该一条记录都不会有。
数据搬运工 2023-7-12 17:55:21
yejr 发表于 2023-7-12 16:48
看了下你上传的截图,每次rollback的事务都不一样的吧。
以后建议上传文字版的,图片看起来太费劲了。 ...

是同一个事务,xid是一样的,我特意选中了xid,如下:
# at 508558359
#230709 14:25:01 server id 7002  end_log_pos 508558660 CRC32 0x74269ca1         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883901/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508558660
#230709 14:25:06 server id 7002  end_log_pos 508558725 CRC32 0x3c4e736d         GTID    last_committed=86220    sequence_number=86221   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956115'/*!*/;
# at 508558725
#230709 14:25:06 server id 7002  end_log_pos 508559026 CRC32 0x56cf76cd         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883906/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508559026
#230709 14:25:06 server id 7002  end_log_pos 508559091 CRC32 0x3e512e5f         GTID    last_committed=86221    sequence_number=86222   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956116'/*!*/;
# at 508559091
#230709 14:25:06 server id 7002  end_log_pos 508559392 CRC32 0xaa035a75         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883906/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508559392
#230709 14:25:08 server id 7002  end_log_pos 508559457 CRC32 0x7fea7337         GTID    last_committed=86222    sequence_number=86223   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956117'/*!*/;
# at 508559457
#230709 14:25:08 server id 7002  end_log_pos 508559758 CRC32 0x267b9474         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883908/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508559758
#230709 14:25:08 server id 7002  end_log_pos 508559823 CRC32 0x912af268         GTID    last_committed=86223    sequence_number=86224   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956118'/*!*/;
# at 508559823
#230709 14:25:08 server id 7002  end_log_pos 508560124 CRC32 0x302c1b49         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883908/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508560124
#230709 14:25:08 server id 7002  end_log_pos 508560189 CRC32 0x3ad4b233         GTID    last_committed=86224    sequence_number=86225   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956119'/*!*/;
# at 508560189
#230709 14:25:08 server id 7002  end_log_pos 508560490 CRC32 0x1af61c16         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883908/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508560490
#230709 14:25:10 server id 7002  end_log_pos 508560555 CRC32 0xffb04a42         GTID    last_committed=86225    sequence_number=86226   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956120'/*!*/;
# at 508560555
#230709 14:25:10 server id 7002  end_log_pos 508560856 CRC32 0xa91d6bba         Query   thread_id=957150        exec_time=0     error_code=0
SET TIMESTAMP=1688883910/*!*/;
XA ROLLBACK X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f677832333836353030303331',X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365
/*!*/;
# at 508560856
#230709 14:25:10 server id 7002  end_log_pos 508560921 CRC32 0x79c9e406         GTID    last_committed=86226    sequence_number=86227   rbr_only=no
SET @@SESSION.GTID_NEXT= '2b46c168-8a20-11ec-ac9a-0050569bfd8f:4956121'/*!*/;
数据搬运工 2023-7-12 17:56:49
数据搬运工 发表于 2023-7-12 17:55
是同一个事务,xid是一样的,我特意选中了xid,如下:
# at 508558359
#230709 14:25:01 server id 7002  ...

X'636f6d2e61746f6d696b6f732e6963617463682e746d5f756e697175655f6e616d655f6a795f6778313230313439',1096044365    事务id是这一串
数据搬运工 2023-7-17 09:59:58
fander 发表于 2023-7-14 12:46
没有使用过XA事务,但mysql XA事务是有bug的,他不是crash safe的,我这个之前就听说过,这篇文章讲述华为 ...

非常感谢您的回复,对我个人有很大帮助。只是产品变更事务框架成本较高,还是期待有另外的解决方法。
数据搬运工 2023-7-21 09:53:07
phoenix.zhang 发表于 2023-7-17 15:19
可以看看 https://bugs.mysql.com/bug.php?id=94130,这是多年前我们进行混沌测试的时候测出过的一个问题 ...

非常感谢您的回复,看症状结果差不多,只是引发原因有点小小的区别:您的案例是多client并发导致,我这边是同一client多次连续执行,请看问题截图中thread_id是相同的。
数据搬运工

1

主题

0

博客

13

贡献

新手上路

Rank: 1

积分
21

合作电话:010-64087828

社区邮箱:greatsql@greatdb.com

社区公众号
社区小助手
QQ群
GMT+8, 2024-11-1 08:39 , Processed in 0.044136 second(s), 17 queries , Redis On.
快速回复 返回顶部 返回列表