背景
mysql 可以支持多种不同的存储引擎,innodb 由于其高效的读写性能,并且支持事务特性,使得它成为 mysql 存储引擎的代名词,使用非常广泛。随着 SSD 逐渐普及,硬件存储成本越来越高,面向写优化的 rocksdb 引擎逐渐流行起来,我们也是看中了 rocksdb 引擎在写放大和空间放大的优势,将其引入到 mysql 体系。两种引擎的结构 B-Tree(innodb 引擎) 和 LSM-Tree(rocksdb 引擎) 很好地形成互补,我们可以根据业务类型来选择合适的存储。一般 mysql 默认是 mysql+innodb 引擎,而 mysql+rocksdb 引擎称之为 myrocks。今天要讨论的就是 myrocks 复制中断问题,案例来源于真实的业务场景。
问题现象
复制过程中,出现了 1756 错误,根据错误日志和 debug 确认是 slave-sql 线程在更新 slave_worker_info 表时出错导致,堆栈如下:
- #7 0x0000000000a30104 in Rpl_info_table::do_flush_info (this=0x2b9999c9de00, force=<optimized out>) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_info_table.cc:171
- #8 0x0000000000a299b1 in flush_info (force=true, this=<optimized out>) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_info_handler.h:92
- #9 Slave_worker::flush_info (this=0x2b9999f80000, force=<optimized out>) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_rli_pdb.cc:318
- #10 0x0000000000a29d95 in Slave_worker::commit_positions (this=this@entry=0x2b9999f80000, ev=ev@entry=0x2b9999c9ab00, ptr_g=ptr_g@entry=0x2b9999daca00, force=<optimized out>)
- at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_rli_pdb.cc:582
- #11 0x00000000009d61f0 in Xid_log_event::do_apply_event_worker (this=0x2b9999c9ab00, w=0x2b9999f80000) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/log_event.cc:74
这里简单介绍下复制相关的位点表,在并行复制模式下,参与复制的主要有三个角色,slave_io 线程负责将主库的 binlog 拉取到本地;slave_sql 线程读取 binlog 并根据一定的规则分发给各个 slave_worker;slave_worker 线程回放主库的操作,达到与主库同步的目的。slave_io 线程和 slave_sql 线程分别只有一个,而 worker 线程可以有 1 个或多个,可以依据参数 slave_parallel_workers 设置。如果将 slave_parallel_workers 设置为 0,则表示关闭并行复制,slave_sql 线程承担回放的工作。位点表主要有 3 张,包括 slave_worker_info,slave_relay_log_info 和 slave_master_info 表。slave_io 线程更新 slave_master_info 表,更新拉取的最新位置;slave_sql 线程更新 slave_relay_log_info 表,更新同步位点; 而 slave_worker 线程更新 slave_worker_info,每个 worker 线程在该表中都对应一条记录,每个 worker 各自更新自己的位点。
Slave_worker 的工作流程如下:
1) 读取 event,调用 do_apply_event 进行回放;
2) 遇到 xid event(commit/rollback event),表示事务结束,调用 commit_positions 更新位点信息;
3) 调用 do_commit 提交事务。
从我们抓的堆栈来看,是 worker 线程在执行执行第 2 步出错,现在我们得到了初步的信息,更新位点表失败直接导致了错误。
问题定位与分析
接下来,我们要看看最终是什么导致了更新位点表失败?根据最后的错误码,我们调试时设置了若干断点,最终得到了如下堆栈
- #0 myrocks::Rdb_transaction::set_status_error (this=0x2b99b6c5b400, thd=0x2b99b6c51000, s=..., kd=std::shared_ptr (count 18, weak 0) 0x2b997fbd7910,
- tbl_def=0x2b9981bc95b0) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/storage/rocksdb/ha_rocksdb.cc:1460
- #1 0x0000000000a6da28 in myrocks::ha_rocksdb::check_and_lock_unique_pk (this=this@entry=0x2b997fbb3010, key_id=key_id@entry=0, row_info=...,
- found=found@entry=0x2b9a58ca77ef, pk_changed=pk_changed@entry=0x2b9a58ca782f)
- at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/storage/rocksdb/ha_rocksdb.cc:7092
- #2 0x0000000000a6e8a8 in myrocks::ha_rocksdb::check_uniqueness_and_lock (this=this@entry=0x2b997fbb3010, row_info=..., pk_changed=pk_changed@entry=0x2b9a58ca782f)
- at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/storage/rocksdb/ha_rocksdb.cc:7250
- #3 0x0000000000a7386a in myrocks::ha_rocksdb::update_write_row (this=this@entry=0x2b997fbb3010, old_data=old_data@entry=0x0
通过代码分析得到了如下信息:
更新位点表之所以失败是因为更新记录时发现已经存在了一条记录,这条记录的 sequnceNumber 比当前快照获取的 sequnceNumber 大,所以报错。这里简单介绍下 sequenceNumber,sequenceNumber 是全局递增的,内部存储为一个 7 字节的整数,Rocksdb 依赖 sequenceNumber 实现 MVCC。每条记录有一个唯一的 sequenceNumber,rocksdb 利用 sequenceNumber 进行可见性判断。事务在提交时,获取当前最大的 sequenceNumber,并按照先后顺序为事务中的每条记录分配一个 sequenceNumber,然后写入 memtable。同一个 key 的多个不同的 sequenceNumber 记录按照逆序存放,即 sequenceNumber 最大的 key 放在最前面,最小的放在最后面。表 1 中 key-n,key 表示 key 值,n 表示 key 对应 sequenceNumber,假设 key1<key2<key3<key4,则存储顺序如下:
Key1-100 |
Key1-50 |
Key2-120 |
Key2-80 |
Key3-70 |
Key4-150 |
ValueA |
ValueB |
ValueC |
ValueD |
ValueE |
ValueF |
进行读取时,会利用 sequenceNumber 建立一个快照,读取快照发生前的已经存在的记录,系统之后的变更与本快照无关。假设快照的 sequenceNumber 是 150,执行 get(key2)时,会找到 (key2-120,ValueC);而如果快照 sequenceNumber 是 100,执行 get(key2) 时,则会找到(key2-80,ValueD)。
回到问题本身,看看与问题相关的更新流程:
1. 尝试对更新 key 加锁,如果没有并发更新,上锁成功 //TryLock
2. 利用当前最大的 sequenceNumberA 生成快照
3. 检查快照生成后,key 是否被修改 // ValidateSnapshot
1) 再次获取最大 sequenceNumberB,构造 key 进行查找 // GetLatestSequenceForKey
2) 查找是否存在相同的 key 的记录
4. 若相同 key 的记录存在,且 key 的 sequnceNumber 大于 sequenceNumberA,则认为有写冲突,报错。
我们碰到的错误正好就是遇到了写冲突报错,那么现在问题来了,明明这个 key 已经上锁了,并且获取了最新的 sequencNumberA,为什么仍然会读到相同的 key,且对应的 seqeunceNumber 比 sequencNumberA 大?结合之前分析的 slave_worker_info 表,我们可以作出以下猜测
大胆猜测:
小心求证:
现象看起来是这么的不合理,所有的假设感觉都是不攻自破,但是事实如此,唯有通过更多的信息来辅佐我们进一步判断。结合代码,我们对于上面怀疑的几个点,在相关路径下进行埋点验证。埋点主要为了得到以下信息:
获得日志如下:
- Resource busy: seq: 38818368818,
- key_seq: 38818368817,
- index number is 0 - 0 - 1 - 2,
- pk is 0 - 0 - 0 - 10,
- thread is 46983376549632映射关系:worker id is 10,
- thread is 46983367104256 //写memtable线程
- worker id is 9,
- thread is 46983376549632 //出错线程
- worker id is 11,
- thread is 46983359772416 //事务提交线程
- 写memtable线程:2016 - 12 - 19 16 : 42 : 06 53743[ERROR] LibRocksDB: In Memtable,
- index_num is 0 - 0 - 1 - 2,
- pk is 0 - 0 - 0 - 10,
- seq is 38818368818,
- thread is 46983367104256 2016 - 12 - 19 16 : 42 : 06 53743[ERROR] LibRocksDB: In Memtable,
- index_num is 0 - 0 - 1 - 2,
- pk is 0 - 0 - 0 - 4,
- seq is 38818368665,
- thread is 46983367104256 2016 - 12 - 19 16 : 42 : 06 53743[ERROR] LibRocksDB: In Memtable,
- index_num is 0 - 0 - 1 - 2,
- pk is 0 - 0 - 0 - 3,
- seq is 38818368675,
- thread is 46983367104256提交线程:type is commit,
- write_start,
- thread is 46983359772416,
- seq is 38818368817 type is commit,
- write_end,
- thread is 46983359772416,
- seq is 38818368818,
- count is 1
报错的直接原因就是 已存在相同 key 的 sequenceNumber 38818368818 大于快照的 squenceNumber 38818368817。这个冲突的 key 由 worker 10 写入 memtable,但是由 worker 11 提交,并不是出错的线程。总结下来, 我们发现几个奇怪的现象:
1. 存在多个线程写一个 key 的情况,比如 worker10 曾经写过 key 为 10,4,和 3 的记录
2. 对于出错的 sequenceNumber(38818368818) 的 key,为什么会被 worker11 提交
3. 日志中发现 SequenceNumber 不连续,存在跳跃的现象
前两个问题很容易让我们陷入误区,存在多个 worker 写同一个 key 的情况,而事实上这两个问题都是源于 group-commit 机制,其它线程可能会代替你提交,导致你会看到同一个 worker 写不同 key 的现象。这里的 group-commit 包括两个层次,server 层 group-commit 和 rocksdb 引擎的 group-commit。
从图中可以看出,在 server 层 group-commit 机制下,流入到 rocksdb 引擎层 commit 接口的都是串行的,既然是串行的,为什么 sequenceNumber 会存在跳跃呢?这时候我想到了 binlog_order_commits 参数,之前为了提高性能,关闭了该参数,也就是在提交的最后一阶段,多个事务并发在引擎层提交,会不会与并发写 memtable 有关,因为在之前复现的过程中,我们发现关闭并发写 memtable 特性 (rocksdb_allow_concurrent_memtable_write=0),问题不会复现。
但令人失望的是,在并发写 memtable 情况下,即使打开了 binlog_ordered_commit(server 层串行 commit),事务串行在引擎层提交仍然会出现同样的问题。
到这里似乎陷入了死胡同,引擎层永远只有一个事务进来,为啥开启并发写 memtable 会影响正确性呢?因为一个事务没法并发。不知什么时候灵光一现,prepare 阶段和 commit 阶段并发。因为 rocksdb 最终提交接口 WriteImpl 是 prepare 和 commit 公用的,通过传入的参数来区别。prepare 阶段写 wal 日志,commit 阶段写 memtable 和 commit 日志。那我们就重点来看 prepare 和 commit 并发进入 WriteImpl 时 SequenceNumber 相关的代码,果然发现了问题。这里我简单介绍下开启并发写 memtable 选项时,事务的提交逻辑。
1. 每个事务都对应一个 write-batch
2. 第一个进入 WriteImpl 函数的线程为 leader,其它线程为 follower
3.leader 和 follower 根据先后顺序串成一个链表
4. 对于并发写 memtable 的情况,leader 根据每个事务 write-batch 的 count,计算每个事务的 start-sequenceNumber。
5.leader 写完 wal 日志后,follower 根据各自 start-sequenceNumber,并发写 memtable
6. 所有事务都写完 memtable 后,leader 更新全局的 sequenceNumber。
问题主要发生在第 4 个步骤,计算 start-sequenceNumber 时,忽略了 prepare 事务的判断,导致在 prepare 事务与 commit 事务成为一个 group 时,commit 事务的 sequence 出现跳跃,而全局的 sequenceNumber 只统计了 commit 事务,最终导致了写入 memtable 的 sequenceNumber 比全局 sequenceNumber 大的现象,进而发生了后续的错误。下面列举一个错误的例子,假设 slave_worker1 和 slave_worker2 分别执行完事务 trx1 和 trx2 操作,更新位点后开始事务提交,trx1 处于 prepare 阶段,trx2 处于 commit 阶段,trx1 和 trx2 组成一个 commit-group, trx1 是 leader,trx2 是 follower,current_sequence 是 101。
- trx1: prepare phase, batch count is 3
- put(user_key1,v1);
- put(user_key2,v2);
- put(user_key3,v3);
- trx2: commit phase, batch count is 2
- put(user_keyA,v1);
- put(user_keyB,v2);
trx1 是 leader,因此 trx2 的 start sequence 是 101+3=104,写入 memtable 中的 user_keyA 的 sequence 是 104,user_keyB 的 sequence 是 105。Current sequence 推进到 103。这个 group 结束后,对于新事务 trx3, 如果 Current sequnce 为已经推进到 120(全局任何事务提交都会推进 sequence),trx3 更新 user_keyA,就会发现已经存在 (user_keyA, 104),也就是我们遇到的错误;而另外一种情况,假设 current Sequence 没有推进,仍然为 103,则会发生更新丢失,因为查不到(user_keyA,104) 这条记录。这正好解释了,为啥我们在同步过程中,会发生丢失更新的问题。
- while (w != pg->last_writer) {
- // Writers that won't write don't get sequence allotment
- if (!w->CallbackFailed()) {
- sequence += WriteBatchInternal::Count(w->batch); # // BUG HERE: not check w-> ShouldWriteToMemtable, sequence out of bound.
- }
- w = w->link_newer;
- w->sequence = sequence;
- w->parallel_group = pg;
- SetState(w, STATE_PARALLEL_FOLLOWER);
- }
小插曲
到这里,我们已经回答了之前的所有疑问,问题也最终定位。但万万没想到,修改代码提交后,复制问题依旧存在,我感叹是不是不只一个 bug。于是继续查,看了下日志,已经不是之前的 slave_worker_info 表出错了,而是一张业务表。后来才发现是因为替换 mysqld 后隔离级别没有设置,重启实例后,隔离级别变为 Read-Repeatable 级别导致。这里简单说下 RR 隔离下,并行复制下,导致上述错误的原因。首先明确一点,RR 隔离是在事务的第一个语句获取快照,以后事务中所有语句都使用这个快照,而 RC 隔离级别则是事务的每个语句会单独获取快照。在并行复制模式下,假设这样一种情况:
时间轴 |
Trx1 |
Trx2 |
1 |
Begin |
Begin |
2 |
Update t1 set v=? where k=1 |
|
3 |
Update t2 set v=? where k=1 |
|
4 |
commit |
|
5 |
Update t2 set v=? where k=1 |
RR 隔离级别下,trx1 会在第一个 update 语句获取快照,更新 t2 表时,仍然使用之前的快照,而在这期间,t2 表的 k=1 对应的记录可能被修改,导致记录的 sequenceNumber 大于 trx1 快照的 sequenceNumber,进而导致更新 t2 失败。而如果是 RC 级别,trx1 执行更新 t2 表时则会重新获取快照,不会存在问题。
问题解决
处理 sequenceNumber 逻辑不正确主要会导致两个问题,备库丢失更新和备库复制中断。定位到问题原因,并且对所有疑问都有合理的解释后,修改就比较简单了,在计算 start-sequenceNumber 函数 LaunchParallelFollowers 中,添加 prepare 事务的判断即可,随后还需要编写测试用例稳定复现,并进行回归测试才算是最终修复这个补丁。我们将问题反馈给官方,很快得到了官方的确认和回复。
总结
整个排查过程还是比较曲折,因为这个 bug 涉及到并发,并且是特定参数组合的并发才会出问题,所以对于这种复杂的场景,通过合理假设与日志埋点能逐步得到一些结论和依据,最后抽丝剥茧获取与问题相关的信息,才最终解决问题。我们在测试验证中过程中不断发现很多看似与预期不符的日志,也正是这些日志让我们把整个流程弄透彻,离解决问题越来越近,总之不要放过任何一个疑点,因为要坚信日志不会骗人,而代码逻辑可能因为你忽略了某些分支,导致会有错误的推断。
来源: