teuthology数据不一致问题分析过程




注意:这个bug非官方引入,因此对使用官方代码的ceph环境没有影响

问题场景

teuthology某个测试用例执行失败,错误原因是数据不一致:

2019-05-30T20:11:18.986 INFO:teuthology.run:Summary data:
{description: 'rados:thrash/{0-size-min-size-overrides/3-size-2-min-size.yaml 1-pg-log-overrides/short_pg_log.yaml
clusters/{fixed-2.yaml openstack.yaml} fs/xfs.yaml msgr-failures/few.yaml test.yaml thrashers/mapgap.yaml workloads/radosbench.yaml}', duration: 579.8200960159302,
failure_reason: '"2019-05-30 20:05:01.881151 osd.5 10.18.192.117:6804/11992 77 :
cluster [ERR] 1.1 shard 1: soid d7cf0021/benchmark_data_hammer004.netease-ceph.com_18678_object192/head//1 size 3145728 != known size 4194304" in cluster log', flavor: basic, owner: cyh, success: false}

并且之前没有跑出来过。没跑出来的原因可能是这个用例没执行到,或者执行到不是必现的。

解决bug第一步:复现bug

要解决bug,第一步必定是找到必现场景,或者高概率复现场景,只有稳定复现的bug,才有希望找到bug原因并修复,否则只能靠推测或者猜测,永远没有办法确认bug是否真正的解决了(加不加修复代码都跑不出来,就不能说问题已经修复了)。

因此这里分两个方向:
1. 分析teuthology测试过程中的ceph日志
2. 直接反复执行失败的用例,看是否可以复现

这两个方向可以并行做,先在已经搭好teuthology环境下写脚本反复执行跑失败的用例,差不多10分钟可以跑完,反复执行看复现概率。

测试执行过程中继续分析之前跑失败的teuthology用例的ceph日志,ceph.log除了上述scrub不一致的错误之外没有别的异常日志,ceph-mon.log里面有所有测试期间收到的客户端操作命令请求,比如osd的up、down、out、reweight、进程退出启动等,然后就是配合rados bench进行io写入,执行完毕功能用例后,进行pg deep-scrub操作,检查是否有数据不一致情况,ceph相关配置项都是在提前配置好的,也有个别是在用例里覆盖掉的。

在看osd日志,除了正常的IO写入外,就是异常的恢复IO,分析srcub发现的不一致对象,找到其所有的IO路径,刚开始没什么头绪,写入过程中涉及到peering、remap等过程,发生过多次Retry,切换过2个主osd,有点被误导,看了一天也只是了解到bug相关场景的基础(或者说用例执行的逻辑),对问题的分析每一实质进展。

分析日志过程中teuthology单独跑测试发现可以复现,并且概率较高(10次必现)。之后继续分析二次复现出来的ceph日志,并尝试更换之前的版本跑相同的用例。

二次复现的日志相对于第一次跑出来的场景要简单许多,不一致的对象是正常写入的,只是osd在恢复对象过程中被打断(osd进程被强制干掉,并且osd是从),然后再次启动后并没有继续恢复流程,最后在scrub过程中发现对象大小不一致,用例执行失败。

尝试老版本复现仍然有问题,也就是说可以排除是本次修改引入的bug,继续使用更老的版本(线上版本)进行复现,仍然可以复现,并且复现概率类似,说明是更早的问题。

根据第二次复现的场景,尝试在本地开发环境使用故障注入的方式进行bug复现,由于是在从osd接收到对象恢复的op后进程被杀掉导致的bug,因此在对应的函数里增加assert(false)操作即可:

diff --git a/src/osd/ReplicatedBackend.cc b/src/osd/ReplicatedBackend.cc
index ee37529..0b298c7 100644
--- a/src/osd/ReplicatedBackend.cc
+++ b/src/osd/ReplicatedBackend.cc
@@ -1941,6 +1941,8 @@ void ReplicatedBackend::handle_push(
                   pop.omap_entries,
                   t);

+  if (!complete && cct->_conf->osd_recover_inject_assert)
+    assert(0 == "xxxxxxxxxxxxxxxxxxxxxxxxx");
   if (complete)
     get_parent()->on_local_recover(
       pop.recovery_info.soid,

添加上述代码后,在osd正在恢复对象的过程中,动态修改配置项osd_recover_inject_assert=true,osd会assert退出,之后再启动这个osd,尝试后发现这个方式可以几乎100%复现这个bug,问题基本就有很大解决的希望了。

首先分析代码流程,发现是osd再次启动后,恢复到一半的对象没有再次加入到missing列表,导致主osd不会再次将其恢复。
但是没有找到根本原因,为啥没有加入missing列表中?因为osd启动时,load_pgs过程中发现这个对象存储(可以读到),并且版本与pg log中的一致,但是为啥对象在?并且版本一致?发现是在分段恢复时,第一段(比如4M中的第1M)恢复的时候就会把对象版本写入对象attrs属性中,之后恢复剩余的部分数据时不会进行修改。

问题的关键就是osd再次启动后对象为啥是存在的?当时怎么也没想明白。

尝试L版本复现

于是尝试分析L版本代码进行对比,发现相关流程并没有改动(load_pgs和分段恢复时第一段设置对象attrs),但用同样的故障注入方式不能复现这个bug,原因是pg的missing对象列表已经跟pglog一起持久化到磁盘上(rocksdb?),只有在对象完全恢复之后才会被删除掉(这部分代码没分析,但猜测肯定是这样),如果按照上面的复现方式进行操作,osd assert退出再启动,pg的missing对象列表在load_pgs时会从rocksdb里加载进来,然后就可以继续恢复。

尝试官方版本复现

分析到这里以为是0.94.6版本本身就有的bug,但问题第一次出现时就google过了,没有搜到任何类似的bug报告,并且tracker.ceph.com上也没有类似bug报告,而且以我们的teuthology复现概率来看,这个bug基本算是必现的,如果官方版本存在,那肯定有人报告。所以就在开发环境通过上面的故障注入方式,搭配官方的0.94.6版本代码进行复现,发现果然是没有问题的,分析到这里基本就可以确认是我们自己修改的代码导致的bug,对比下线上版本和官方0.94.6版本,看到基本唯一的改动就是部分恢复功能,基本可以确认这个功能引入的(其实问题一出现我们就怀疑这部分代码,当时应该第一时间确认,就可以少走很多弯路,但也就意味着少学习很多东西)。

分析部分恢复优化代码

分析部分恢复优化代码,可以看到在submit_push_data函数里有修改数据恢复的pg目录(head还是TMP):

void ReplicatedBackend::submit_push_data(
  ObjectRecoveryInfo &recovery_info,
  bool first,
  bool complete,
  const interval_set<uint64_t> &intervals_included,
  bufferlist data_included,
  bufferlist omap_header,
  map<string, bufferlist> &attrs,
  map<string, bufferlist> &omap_entries,
  ObjectStore::Transaction *t)
{
  coll_t target_coll;
  bool can_recover_partial = recovery_info.can_recover_partial;
  if (first && complete || can_recover_partial) {  // 这里can_recover_partial几乎永远为true,所以target_coll就是pg的head目录,而不是tmp目录
    target_coll = coll;
  } else {
    dout(10) << __func__ << ": Creating oid "
         << recovery_info.soid << " in the temp collection" << dendl;
    add_temp_obj(recovery_info.soid);
    target_coll = get_temp_coll(t);  // 官方的分段恢复是走这里,在pg的tmp目录下进行恢复,对象全部恢复完毕之后再move到head目录
  }

  if (first) {
    if (!can_recover_partial) {
      get_parent()->on_local_recover_start(recovery_info.soid, t);
      t->remove(get_temp_coll(t), recovery_info.soid);
      t->touch(target_coll, recovery_info.soid);
      t->truncate(target_coll, recovery_info.soid, recovery_info.size);
    }
    t->omap_setheader(target_coll, recovery_info.soid, omap_header);
  }
  uint64_t off = 0;
  for (interval_set<uint64_t>::const_iterator p = intervals_included.begin();
       p != intervals_included.end();
       ++p) {
    bufferlist bit;
    bit.substr_of(data_included, off, p.get_len());
    t->write(target_coll, recovery_info.soid,
         p.get_start(), p.get_len(), bit);
    off += p.get_len();
  }

  t->omap_setkeys(target_coll, recovery_info.soid,
          omap_entries);
  t->setattrs(target_coll, recovery_info.soid,  // 如果按照官方的代码逻辑,部分恢复场景下,这里的target_coll是pg的tmp目录,但是我们增加部分恢复功能之后,这里就是直接在pg的head目录下修改对象属性了,导致上面复现场景下,二次重启后,检查对象版本时可以在pg的head目录下读到对象的属性,而且与pg log中的一致,导致pg认为这个对象是正常的,没有加入pg的missing对象列表(列表会在peering的GetMissing阶段发给主osd),主osd就不会主动恢复这个对象,最终pg deep scrub的时候发现对象数据大小不一致。
          attrs);

  if (complete) {
    if (!first && !can_recover_partial) {
      dout(10) << __func__ << ": Removing oid "
           << recovery_info.soid << " from the temp collection" << dendl;
      clear_temp_obj(recovery_info.soid);
      t->collection_move(coll, target_coll, recovery_info.soid);
    }

    submit_push_complete(recovery_info, t);
  }
}

解决方案

因此就加入日志进行复现,发现确实是如此,确认问题之后就是找解决方案了,组长建议把分段恢复功能关闭(注意是官方的分段恢复,而不是我们修改的部分恢复,部分恢复是指分段里面的一部分,比如1M分段中的128K数据,这个功能可以减少实际需要恢复的数据量),也即把osd_recovery_max_chunk配置项设置为默认值(8388608),当前我们线上和teuthology测试用的都是131072。这样的话,

  bool can_recover_partial = recovery_info.can_recover_partial;
  if (first && complete || can_recover_partial) {  // 这里保证first&&complete为true,target_coll就是pg的head目录,一次恢复全部数据,并且由事务保证要么成功,对象存在且是完整恢复的,要么失败,对象完全不存在,不会处于中间状态
    target_coll = coll;
  } else {
    dout(10) << __func__ << ": Creating oid "
         << recovery_info.soid << " in the temp collection" << dendl;
    add_temp_obj(recovery_info.soid);
    target_coll = get_temp_coll(t);
  }

尝试修改配置项之后用故障注入方式及teuthology单独执行相关bug用例,不一致问题均不再出现,问题确认修复。

可以看出,问题分析过程虽然比较曲折,但问题的原因分析清楚之后,却非常简单,改动方案也很简单。一般来说改动方案越简单,才说明找到了真正的问题点。