记一个P0+的Bug
背景
在产品TR5阶段的测试中,和存储团队对接的管理面团队发现Oracle的日志归档程序报错,具体为redo日志文件损坏。 在梳理问题后得到最初的一些背景:
- redo 日志是循环覆写的
- 每次写入512字节
- 512字节前16字节包含了日志的元数据,可以用来校验日志文件的完整性
- 开启了条带化,参数为
stripe_length: 32, stripe_width: 32
- 必现,但时间跨度大,从2小时到4小时不等
- 全流程数据校验没有报错
初步应对
首先数据肯定是错了,具体哪里出了问题还没有结论,但可以初略分成两个部分:
- raft 三副本复制错误
- localstore 读取错误
- frontend 条带化错误
由于复现需要耗时很久,现场可以直接读这个错误的文件,然后将IO用blktrace
录制下来,根据录制在localstore通过命令行工具校验三个副本的数据是否一致。
在关闭所有影响录制IO的进程后,重新读取错误的redo日志录制IO,得到数百个IO模型,frontend组编写脚本,将blktrace录制的IO转化为存储内部使用的chunk_id
、offset
、volume_id
、pg_id
等数据,再由localstore组编写脚本,使用这些数据对比三副本数据。
结果发现,这些数据块上根本没有写过数据!
反复确认,发现frontend组的脚本没有正确的配置条带化参数以及卷id。
由于复现困难,管理面还需要使用环境做其他测试,初步应对宣告失败。
另一种思路
根据背景中掌握的信息,可以推测是 512 字节小IO的某种模式触发了存储的bug,同时由于blktrace
抓下来的IO还需要通过脚本转换, 并且脚本可能出错(使用了不同于frontend运行时的配置),安排如下:
- 编写一个测试程序,模拟512字节小IO读写的各种模式
- frontend 中增加类似
blktrace
的功能,通过命令行直接导出chunk_id
、offset
、length
等数据
- localstore 着重梳理小IO合并相关代码
经过一天的努力,以上三个任务都已经完成,在春节期间,使用测试程序进行不间断的测试。
春节结束后,回顾测试,发现仅复现了一次,测试结果显示:读请求读到了旧的数据。
为了确保不再发生参数错误的问题,raft组代表被要求review这个测试程序,同时检查raft组的相关代码,是否存在读到旧数据的问题。frontend组被要求梳理条带化相关代码。同时,在存储内部的性能环境上搭建Oracle测试环境,用于复现问题。
这种方式也以失败告终。
为什么数据校验没有报错
对于数据本身就写错的情况,数据校验无法检查。 针对这种情况,在存储中的各个模块的读写请求增加额外的检查(chksec模块),分配一大块内存(数据错误位置大约是300M,所有这个方法可行,否则内存不够用)每一个写请求的512字节都算一个checkcusm,在读请求完成时重新计算checksum,和写时记录的对比。
任务安排如下:
- frontend 、raft 和 localstore 负责修改组内代码,增加chksec
- 测试人员负责复现
测试发现,存储中的所有模块都在报错误,这不得不怀疑chksec模块的正确性,于是
raft 和 localstore 负责review chksec的实现
frontend 不用闭关了,梳理 frontend 和 rdma_crpc 的实现
经过两三天的调试,发现报错的原因有好几个:多路径策略是 round-robin,这会导致同一个地方写入多次
Oracle的仲裁盘也会存在几个主机写同一个地方的情况
chksec 没有处理以上情况,导致误报
接下来怎么办
经历了一系列的措施,仍然没有将问题范围缩小。 任务安排如下:
- frontend 自己把问题分成两半
- raft 和 localstore 一起解决chksec遇到的问题
- 测试继续复现问题,确保不是chunk_server
frontend的工作
好消息是存储中的模块有明显的界限,从frontend到crpc仅经历了网络传输,从crpc到localstore才经历了raft。另外,由于前期已经拿到了redo日志错误的读取模式(凭借公司DBA丰富的经验),能够稳定的复现出来。frontend组将crpc模块中错误IO模式对应得chunk镜像到文件中,同时frontend中也做相同的事。然后对比写入的数据和读取的数据是否一致。
结构发现,crpc中写入和读取完全一致,frontend中出现了不一致的情况,因此可以确定问题一定出在frontend中。
随后在frontend中针对出错的IO模式增加日志打印,发现:
- 在4M边界一次性读103个sector (512bytes)数据正常
- 在4M边界偏移一个sector,再读取 102 个sector,数据出现错位
并且,错误仅出现在最后的7个sector,于是怀疑是条带化的问题(前面已经梳理过条带化的代码,没发现问题)。
在条带化的代码中增加额外的日志,对比以上两种IO模式发现,第一种IO会被拆成 32 + 32 + 32 + 7 个子IO,第二种IO会被拆成 31 + 32 + 32 + 7 个子IO,注意到数据出错是最后的 7 个IO。
通过对比发现,出现错误的IO模式的倒数第7个IO在发送时被拆成了两个iovec
:
iov[0].iov_len 512
iov[1].iov_len 3072
而crpc回复时是一个WR
(RDMA Work Request),最早在实现时约定,IO不足4k的单独使用一个WR
发送,frontend会根据header后的64位拿到这个不足4k的数据的真实长度,一次性获取完。这部分代码如下:
static void parse_8bytes(struct conn_ctx *c, char *iov)
{
ASSERT(c->p_status == P_8B);
uint64_t _offset = 0;
SPDK_INFOLOG(chunk_client_utils, "recv 8bytes id 0x%lx length %lu",
c->rpl_hdr->request_id, c->_8b);
if ((c->rpl_hdr->nr_chksum > 0) &&
proc_chk_point_is_enable(PROC_CHK_POINT_FE_READ))
cal_rcv_chksum(c, iov, c->_8b);
while (_offset < c->_8b) {
char *dst = c->rio->iov[c->r_idx].iov_base;
uint64_t sz = spdk_min(c->_8b - _offset,
c->rio->iov[c->r_idx].iov_len);
memcpy(dst, iov, sz);
c->r_offset += sz;
_offset += sz;
ASSERT(c->rpl_hdr->bytes >= sz);
c->rpl_hdr->bytes -= sz;
if (c->rpl_hdr->bytes == 0) {
// _8b maybe less than 4k
if (c->rpl_hdr->nr_chksum > 0) {
c->p_status = P_CHKSUM;
return;
}
ASSERT(c->_8b <= MEMPOOL_ELEM_SZ);
parse_done(c);
return;
}
if (c->r_offset == c->rio->iov[c->r_idx].iov_len) {
c->r_offset = 0;
c->r_idx += 1;
}
}
c->p_status = P_DATA;
}
可以看到,它是正确处理了本地拆分成的两个iovec
的,但问题是,在循环过程种源iov
的偏移没有增加
memcpy(dst, iov, sz);
这导致dst
的前512字节会被覆盖掉,感觉像是数据被往前移动了512字节。
修改如下:
memcpy(dst, iov + _offset, sz);
这段代码同时也解释了为什么数据校验没有检查出错误:因为错误发生在数据校验之后。
总结
这个bug暴露了好几个问题:
- 测试不够,这个问题是其他团队发现的,存储团队没有测试出来,并且存储团队虽然有不同IO模型的测试用例,但测试组没有执行起来
- 定位手段仍然欠缺,
blktrace
、chksec
本可以有很大的用途,但工具本身的问题让效果大打折扣(chksec 看出frontend读请求的checksum个写请求呈现出新旧交替的效果,但并未指出问题所在)
- 一个功能的修改并没有测试联想到可能导致的问题,以上的代码在条带化之前是不可能出现的
- 代码review和单元测试存在疏忽,以上代码单元测试和系统测试都能覆盖到,但循环仅执行了一次,没有触发问题
- 数据校验应该放在离主机最近的地方,这里计算校验后还进行了拷贝,违背了原则