一个导致MGR数据混乱Bug的分析和修复

1、背景

MGR是个好东西,因为他从本质上解决了数据不一致的问题。不光是解决了问题,而且出自名门正派(Oracle的MySQL团队),对品质和后续的维护,我们是可以期待的。

但是在调研的过程中,发现有个严重的bug(https://bugs.mysql.com/bug.php?id=92690),在网络有延迟、丢包和数据损坏时,会导致各个节点间数据严重不一致。而上述网络情况,在跨地域部署时候,出现的概率还是比较高的,因此,必须解决上述问题。我也一直在等待官方团队的修复(该bug在2018年11月5号被提出,截止到写作这篇文章,已经3个月了),但是一直没有bug fix放出。

2、社区对于该bug的分析

a)相同gtid编号,内容不同

从这个bug submmiter的分析来看,即使是相同的gtid编号,其内容也不相同,甚至操作的表都不一样。

gr01 > show binlog events in 'binlog.000223' from 11590 limit 11;
+---------------+-------+-------------+-----------+-------------+------------------------------------------------------------------------+
| Log_name      | Pos   | Event_type  | Server_id | End_log_pos | Info                                                                   |
+---------------+-------+-------------+-----------+-------------+------------------------------------------------------------------------+
| binlog.000223 | 11590 | Gtid        |        10 |       11651 | SET @@SESSION.GTID_NEXT= 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa:295533' |
| binlog.000223 | 11651 | Query       |        10 |       11723 | BEGIN                                                                  |
| binlog.000223 | 11723 | Table_map   |        10 |       11775 | table_id: 125 (db1.sbtest6)                                            |
| binlog.000223 | 11775 | Update_rows |        10 |       12185 | table_id: 125 flags: STMT_END_F                                        |
| binlog.000223 | 12185 | Table_map   |        10 |       12237 | table_id: 116 (db1.sbtest5)                                            |
| binlog.000223 | 12237 | Update_rows |        10 |       12647 | table_id: 116 flags: STMT_END_F                                        |
| binlog.000223 | 12647 | Table_map   |        10 |       12699 | table_id: 118 (db1.sbtest1)                                            |
| binlog.000223 | 12699 | Delete_rows |        10 |       12919 | table_id: 118 flags: STMT_END_F                                        |
| binlog.000223 | 12919 | Table_map   |        10 |       12971 | table_id: 118 (db1.sbtest1)                                            |
| binlog.000223 | 12971 | Write_rows  |        10 |       13191 | table_id: 118 flags: STMT_END_F                                        |
| binlog.000223 | 13191 | Xid         |        10 |       13218 | COMMIT /* xid=6231928 */                                               |
+---------------+-------+-------------+-----------+-------------+------------------------------------------------------------------------+
11 rows in set (0.00 sec)

gr02 > show binlog events in 'binlog.000221' from 9912 limit 11;
+---------------+-------+-------------+-----------+-------------+------------------------------------------------------------------------+
| Log_name      | Pos   | Event_type  | Server_id | End_log_pos | Info                                                                   |
+---------------+-------+-------------+-----------+-------------+------------------------------------------------------------------------+
| binlog.000221 |  9912 | Gtid        |        10 |        9973 | SET @@SESSION.GTID_NEXT= 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa:295533' |
| binlog.000221 |  9973 | Query       |        10 |       10037 | BEGIN                                                                  |
| binlog.000221 | 10037 | Table_map   |        10 |       10089 | table_id: 108 (db1.sbtest5)                                            |
| binlog.000221 | 10089 | Update_rows |        10 |       10499 | table_id: 108 flags: STMT_END_F                                        |
| binlog.000221 | 10499 | Table_map   |        10 |       10551 | table_id: 110 (db1.sbtest4)                                            |
| binlog.000221 | 10551 | Update_rows |        10 |       10961 | table_id: 110 flags: STMT_END_F                                        |
| binlog.000221 | 10961 | Table_map   |        10 |       11014 | table_id: 109 (db1.sbtest10)                                           |
| binlog.000221 | 11014 | Delete_rows |        10 |       11234 | table_id: 109 flags: STMT_END_F                                        |
| binlog.000221 | 11234 | Table_map   |        10 |       11287 | table_id: 109 (db1.sbtest10)                                           |
| binlog.000221 | 11287 | Write_rows  |        10 |       11507 | table_id: 109 flags: STMT_END_F                                        |
| binlog.000221 | 11507 | Xid         |        10 |       11534 | COMMIT /* xid=1185380 */                                               |
+---------------+-------+-------------+-----------+-------------+------------------------------------------------------------------------+
11 rows in set (0.00 sec)

b)相同的paxos信息编号,消息类型不同

社区内有人在MGR源码中加入日志,分析出相同编号的paxos信息,在Primary节点上是带有实际的信息(和应用相关的,比如binlog的信息),但是在Secondary节点上是空消息(noop,不会提交给应用)。因此出现了数据不一致。

c)prepare阶段出现问题

注意,这里的prepare和数据库概念无关,而是paxos中的prepare。相关概念参考这篇博客(http://mysqlhighavailability.com/the-king-is-dead-long-live-the-king-our-homegrown-paxos-based-consensus/)。下图中的Election和prepare的含义是一样的。

 

简要来说,任何一个节点在发送一个消息的时候,

1)先发送prepare消息,以确定其要发起提议的值;  

2)根据上一步的结果,发送accept信息到各个参与节点;

3)如果收到多数派的回应,则发送learn信息,如果其他节点(比如节点1)收到learn信息,则消息的值,(在节点1)被确认了。

从上面可以看出,一个消息的发送,需要经过3个阶段,不仅产生了较大的网络流量,更糟糕的是整个消息,从被发起到被确认经历了较大延迟。

因此很多paxos的变种,都会试图去优化这个过程。比如在系统运行稳定时,省略了第一步的prepare阶段。但是在系统不稳定时,比如某个节点发现其缺少某个编号的消息时,会走完整的三阶段。

而该bug正好就是在网络很糟糕的情况下出现,因此有很大可能性就是prepare阶段出现了问题。

3、相关概念补充

a)节点编号

每个节点都有一个编号。比如一个MGR集群,有三个节点,那么其编号就分别是0,1,2。其中编号的大小与是否为Primary无关

b)消息编号

消息编号由两部分组成,第一部分是64位的无符号数,一般是递增的,另一部分是节点编号。

比如(10064,0)就是一个消息编号

c)投票号

投票号也是由两个部分组成,第一部分是32位的有符号数,另一部分也是节点编号。

4、笔者分析

a)分析方法

之前所熟悉和擅长的方法,尤其是调试方式上,在分布式系统中显得力不从心。比如在研发智能SQL优化器时,利用gdb,帮助我了解了很多优化器的细节。但是对于分布式系统来说,一旦使用gdb挂载,可能会对其行为产生影响。因此笔者采用,以日志为主,gdb为辅的调试方法

b)paxos消息分析

1)结果正确、网络正常

节点编号:0,Primary节点

in push_msg_2p msg_no 1683, 0
in dispatch_op msg_no 1683, 0, paxos op accept_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op ack_accept_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op ack_accept_op from : 2 to : 0
in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op ack_accept_op from : 1 to : 0
msg_no 1683, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op


节点编号:2,Secondary节点

in dispatch_op msg_no 1683, 0, paxos op accept_op from : 0 to : 2
in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 2
msg_no 1683, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op


节点编号:1,Secondary节点

in dispatch_op msg_no 1683, 0, paxos op accept_op from : 0 to : 1
in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 1
msg_no 1683, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op

分析:

A)0号节点发送编号为(1683,0)的消息

in push_msg_2p msg_no 1683, 0

B)0,1、2号节点均收到accept_op

in dispatch_op msg_no 1683, 0, paxos op accept_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op accept_op from : 0 to : 2
in dispatch_op msg_no 1683, 0, paxos op accept_op from : 0 to : 1


C)0,1、2号节点均回复ack_accept_ok

in dispatch_op msg_no 1683, 0, paxos op ack_accept_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op ack_accept_op from : 2 to : 0
in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op ack_accept_op from : 1 to : 0

注意到0号节点在收到2个ack_accept_ok(大多数)时,就开始发送tiny_learn_op,其中0号节点立即收到了这个消息

D)0、1、2号节点收到tiny_learn_op,表示消息在各个节点确认了。

in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 0
in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 1
in dispatch_op msg_no 1683, 0, paxos op tiny_learn_op from : 0 to : 2

E)0、1、2号节点将收到的信息,传送给上层应用

msg_no 1683, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op
msg_no 1683, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op
msg_no 1683, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op

2)结果正确、网络不正常

节点编号:0,Primary节点
in push_msg_2p msg_no 44043, 0
in dispatch_op msg_no 44043, 0, paxos op accept_op from : 0 to : 0
in dispatch_op msg_no 44043, 0, paxos op ack_accept_op from : 0 to : 0
in dispatch_op msg_no 44043, 0, paxos op ack_accept_op from : 2 to : 0
in dispatch_op msg_no 44043, 0, paxos op tiny_learn_op from : 0 to : 0
msg_no 44043, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op

节点编号:2,Secondary节点
in dispatch_op msg_no 44043, 0, paxos op accept_op from : 0 to : 2
in dispatch_op msg_no 44043, 0, paxos op tiny_learn_op from : 0 to : 2
msg_no 44043, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op
in dispatch_op msg_no 44043, 0, paxos op read_op from : 1 to : 2


节点编号:1,Secondary节点
in read_missing_values msg_no 44043, 0
in dispatch_op msg_no 44043, 0, paxos op learn_op from : 2 to : 1
msg_no 44043, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op

 分析:

对比情况 1),有如下几个发现

A)0号节点,只收到两个ack_accept_op(来自0、2号),其中缺失了1号节点的回复。但是由于构成了多数派,还是能够成功。

B)1号节点发现缺少编号(44043,0)的信息后,往节点2发送read_op的信息,以获取缺失的信息

in dispatch_op msg_no 44043, 0, paxos op read_op from : 1 to : 2

C)2号节点,将信息发给1号节点

in dispatch_op msg_no 44043, 0, paxos op learn_op from : 2 to : 1

3)节点错误、网络不正常

节点编号:0,Primary节点
in push_msg_2p msg_no 44044, 0
in dispatch_op msg_no 44044, 0, paxos op accept_op from : 0 to : 0
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 0 to : 0
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 2 to : 0
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 0 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op prepare_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op accept_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 2 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 2 to : 0
msg_no 44044, 0 cargo_type : app_type , msg_type : normal, pax_op : learn_op

节点编号:2,Secondary节点
in dispatch_op msg_no 44044, 0, paxos op accept_op from : 0 to : 2
in read_missing_values msg_no 44044, 0
in read_missing_values msg_no 44044, 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 1 to : 2
in read_missing_values msg_no 44044, 0
in dispatch_op msg_no 44044, 0, paxos op prepare_op from : 1 to : 2
in dispatch_op msg_no 44044, 0, paxos op accept_op from : 1 to : 2
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 1 to : 2
msg_no 44044, 0 is no_op
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 0 to : 2
in dispatch_op msg_no 44044, 0, paxos op learn_op from : 0 to : 2
in dispatch_op msg_no 44044, 0, paxos op learn_op from : 0 to : 2

节点编号:1,Secondary节点
in read_missing_values msg_no 44044, 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 2 to : 1
in read_missing_values msg_no 44044, 0
in read_missing_values msg_no 44044, 0
in push_msg_3p msg_no 44044, 0
in dispatch_op msg_no 44044, 0, paxos op prepare_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_prepare_empty_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_prepare_op from : 2 to : 1
in dispatch_op msg_no 44044, 0, paxos op accept_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 2 to : 1
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 1 to : 1
msg_no 44044, 0 is no_op

 分析:

A)0号节点发送消息(44044, 0),只有0、2节点回复了。

in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 0 to : 0
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 2 to : 0

B)0号节点,发送tiny_learn_op,但是只有0号节点收到了,此时编号为(44044, 0)的消息,在0号节点确定了,但是2号节点还未及时收到tiny_learn_op

msg_no 44044, 0 is no_op
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 0 to : 2

注意2号节点,在消息(44044, 0)被确定为no_op时,才收到tiny_learn_op。也就是说这个tiny_learn_op对于2号节点来说,就像没收到过一样

C)1、2号节点,试图读取缺失的(44044, 0)消息(通过发送read_op),但是由于网络问题,均没有得到及时的回复 

in dispatch_op msg_no 44044, 0, paxos op read_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 1 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 2 to : 0
in dispatch_op msg_no 44044, 0, paxos op read_op from : 2 to : 0

D)1号节点试图针对(44044, 0)发起noop消息提议

in push_msg_3p msg_no 44044, 0

注意关键点,错误在下一步

E)节点1试图获得他应该提议的值,并完成了propose过程

in dispatch_op msg_no 44044, 0, paxos op prepare_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_prepare_empty_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_prepare_op from : 2 to : 1
in dispatch_op msg_no 44044, 0, paxos op accept_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 1 to : 1
in dispatch_op msg_no 44044, 0, paxos op ack_accept_op from : 2 to : 1
in dispatch_op msg_no 44044, 0, paxos op tiny_learn_op from : 1 to : 1
msg_no 44044, 0 is no_op

E.1)节点1发送prepare_op,并收到了节点1、2的回复

E.2) 节点1是没有值(因为其之前没有收到过来自节点0的accept_op),所以其回复ack_prepare_empty_op

E.3) 节点2有值(参考A),所以其回复ack_prepare_op

E.4)原则上节点1会发起节点2返回给的值,但是从结果来看,其并没有

msg_no 44044, 0 is no_op

针对这个问题,笔者仔细阅读MGR的prepare阶段的源码,核心代码为

int gt_ballot(ballot x, ballot y) {
  return x.cnt > y.cnt || (x.cnt == y.cnt && x.node > y.node);
}

只有满足这个条件,节点1才会使用节点2返回的值。

F)进一步研究发现,凡是编号大的节点发起的noop提议都有可能会有上述问题。

in handle_ack_prepare msg_no 82876, 0, m->proposal.cnt = 0, m->proposal.node = 0, p->proposer.msg->proposal.cnt = 0, p->proposer.msg->proposal.node = 1

由于初始化的时候,cnt均为0,大小完全取决于节点编号。 本例中为 0 < 1 , 所以无法使用0的值

 5、解决办法

static void propose_noop(synode_no find, pax_machine *p) {
  /* Prepare to send a noop */
  site_def const *site = find_site_def(find);
  assert(!too_far(find));
  replace_pax_msg(&p->proposer.msg, pax_msg_new(find, site));
/* set cnt to -1 when propose noop*/
int cnt = -1; node_no nodeno = VOID_NODE_NO; if (site) nodeno = get_nodeno(site); init_ballot(&p->proposer.msg->proposal, cnt, nodeno);
/* set cnt to -1 when propose noop*/ assert(p
->proposer.msg); create_noop(p->proposer.msg); //printf("in propose_noop msg_no %lld, %d ", p->proposer.msg->synode.msgno, p->proposer.msg->synode.node); //fflush(stdout); /* DBGOUT(FN; SYCEXP(find);); */ push_msg_3p(site, p, clone_pax_msg(p->proposer.msg), find, no_op); }

代码中红色部分为增加部分。修改后,由于 -1 < 0, 所以解决了那个问题。

原文地址:https://www.cnblogs.com/youge-OneSQL/p/10388531.html