pika_hub debug日记1 ·

22 September 2017

pika_hub debug日记1

最近同事测试pika_hub时发现在某些情况下多实例同步会丢数据，测试5个pika实例相互同步总量5000万条数据，结果有2实例各丢10条左右，找了好一阵子，最终解决了，写篇博客给自己记录一下吧

1. pika_hub如何读写binlog

在写pika_hub前，自己已经对pika现有的binlog读写方式不太满意，在多线程边读边写的场景，pika是这么做的：

1. 写binlog前加锁，这个没什么异议，为了保证写入的完整。但有一个
   manifest文件很蛋疼，这个就是为了记录写入的当前偏移量，其实用
   binlog文件的自然大小就可以的，可当初还是用了一个manifest来
   记录，导致每写一条就得更新manifest，还得sync一下，很丑很低效。
2. 读binlog前加锁，判断自己上次读的问题和binlog现在位置的大小，
   一样的话则放锁sleep一段时间重试，不一样的话，放锁读。这本身
   没什么问题，可以每次读之前都加锁判断一下，很影响writer的效率，
   同样低效

反思了pika的问题后，我在pika_hub的binlog实现中采用了新的做法

1. 直接使用文件的自然大小，去掉多余的manifest，并且每一条record
   都做了crc32校验
2. reader在读之前不需要加锁，直接无脑读，如果判断到EOF时再加锁，
   wait到condition上，writer后续写入后会signal，唤醒reader接着读

2. Bug定位

测试发现但凡丢的数据都是在个别binlog的最后，排查各种其他原因后，最终猜测应该是在binlog切文件时引发的问题。reader读binlog的过程大概如下：

while (!should_exit_) {
    ret = reader_->ReadRecord(&record, &scratch);
    if (ret) {
      DecodeBinlogContent(record, result);
      return rocksutil::Status::OK();
    } else {
      if (status_.ok()) {
        manager_->mutex()->Lock();
        manager_->GetWriterOffset(&writer_number, &writer_offset);
        reader_offset = reader_->EndOfBufferOffset();
        while (number_ == writer_number && reader_offset == writer_offset) {
          /*
           * if exit_at_end_ is TRUE,
           * return directly when all the content have been read
           * this mode is used in BinlogManager lru recovering
           */
          if (exit_at_end_) {
            manager_->mutex()->Unlock();
            return rocksutil::Status::Corruption("Exit");
          }
          /*
           * if exit_at_end_ is FALSE
           * wait until new content is written or should exit;
           */
          manager_->cv()->Wait();
          if (should_exit_) {
            manager_->mutex()->Unlock();
            return rocksutil::Status::Corruption("Exit");
          }
          manager_->GetWriterOffset(&writer_number, &writer_offset);
          reader_offset = reader_->EndOfBufferOffset();
        }
        
        reader_->UnmarkEOF();
        manager_->mutex()->Unlock();
        rocksutil::Status s = env_->FileExists(log_path_ + "/" + kBinlogPrefix +
              std::to_string(number_+1));
        if (s.ok()) {
          TryToRollFile();
        }
        } else {
        return status_;
      }
    }
  }

当被writer唤醒后，reader会检查writer当前的offset和自己的offset，如果一样，表示没有新内容写入，就继续wait，如果不一样（filenum不一样或者文件内offset不一样），则跳出循环，此时reader会判断下一个binlog文件是否存在，如果存在，就切到下一个文件去读，如果不存在，就继续读本文件。

问题就出在这里，假设reader在读binlog_1的末尾时发现EOF，进行wait，然后writer又在binlog_1的末尾写了一条数据，并且唤醒reader，并且！此时writer判断binlog_1大小大于100M需要切到binlog_2，如果在reader判断是否存在下一个文件之前，writer就创建了binlog_2，那么reader进行判断后就直接切到binlog_2开始读，导致binlog_1的最后几条数据丢失。

原因找到了，解决也很简单，在被唤醒并且跳出condition循环后，先判断当前文件实际大小和自己的read_offset是否一样，一样的话肯定是读完当前文件了，接着判断是否要切下一个文件读，不一样的话，就接着读当前文件，不切。

3. 意外发现

这个bug其实也不难（往往找到后都觉得不难^^），不过好玩的是在修复的时候，我发现了新的问题。之前在reader被唤醒之后，做的是先UnmarkEOF再Unlock，后来感觉没必要在锁里UnmarkEOF，就改成先Unlock再UnmarkEOF，然后测试就会报checksum错误，很好奇原因，就继续排查了一下。

先说下UnmarkEOF用来干嘛，rocksutil对wal文件的ReadRecord实现中，如果读到文件尾，就会进入eof状态，怎么判断是文件尾呢，就是某次Read出来的内容大小不足一个Block的大小（32K）。如果后续文件又写了新的内容，在接着读之前，需要执行UnmarkEOF，先将上次读取的最后一个不全的Block读完，这样后续的Read才能继续每次按照32K来卡。

既然UnmarkEOF就是做了次read，那么放在锁里和锁外为什么差别这么大呢？

放在锁里没问题，在UnmarkEOF进行read时，writer肯定不会写新的内容，放在锁外的话，read时writer有可能会在写新的内容。

我给rocksutil的log_reader加了各种调试日志，跑了N多次，最终找到了原因：

放在锁内，read时肯定读出的是完整的一条record（至少内容和Header记录相符，因为肯定是writer写完这条record后才唤醒reader），如果放在锁外，当UnmarkEOF进行read尝试补齐上次没读全的Block时，writer拿到锁会同时写这个Block剩余部分，所以reader有可能read出一条半的内容，当开始解析时，首先第一条没有问题，解析成功。剩下的半条，如果小于kHeaderSize，那么就会尝试ReadMore，也没问题，如果大于KHeaderSize，但通过它的Header拿到的record length大于当前buffer里的内容大小，rocksutil会直接drop掉这个buffer(因为rocksutil实现的是write ahead log，默认读写文件不是同时进行，读的时候出现这个问题，肯定是当初写文件写到最后没写完崩掉了，所以要丢弃这些垃圾内容)，如果这个buffer的内容被丢弃掉，返回kBadHeader，那么后续的读取全都发生错位，我看到的现象是后续拿到type=12（kOldRecord），然后不再读取新内容，解析停止了。

所以，UnmarkEOF只能放在锁里，不然read和write同时进行，很容易读出半条信息，而在rocksutil的实现里，半条信息的错误是不可恢复的。

3. 总结

pika_hub对rocksutil里write ahead log的用法还是有些风险，毕竟那本是write ahead log，不是专门用来边读边写的。理论上即使不在UnmarkEOF，正常的ReadRecord里也会读出半条信息，只不过实际线上读写不用那么巧合碰到一起。我暂时选择继续使用rocksutil的wal来做binlog，只不过在pika_hub里加了容错，一旦出现checksum错误，我会立刻关闭这个reader，重新打开新的reader，定位到上次的成功读取的位置，尝试再次读取这里，一般情况下，writer此时已经写完了这个block，会成功的。

等pika_hub写完之后，感觉有必要给rocksutil加一个真正适合边读边写的Binlog实现了。