物理机假死事件

物理机假死事件

最近在处理 ckb 的一个 issue ,看上去并不奇特,但复现之后,非常麻烦。大意就是,在某些特定场景下,ckb 的行为会导致运行 ckb 的服务器假死,无法响应。坦白而言,这种行为几乎超出了我的认知,简直属于魔法攻击了,一般程序在运行时基本不太可能会导致物理机假死,除非发出了硬件攻击,对 io 发出了强烈的 ddos 攻击等等,我们复现之后,才发现,卡死状态下,终端无法使用,top 之类的状态不再更新,甚至怀疑在这种情况下,只有内核态的东西在工作,用户态的东西都停止工作了。为什么能确认内核态在工作,很简单,在不确定时间后(几个小时不等),机器可能会恢复正常。简而言之,出现问题的时候,无法进行观测,而无法观测就意味着无法确认问题,非常令人头疼的状态。

拆(猜)程序(一)

debug 有时候和猜本质上没有什么区别,都是根据现象,猜测问题,然后去验证,反复上述过程,直到找到最后的答案。

在稳定复现的基础上,要做到确认问题的情况,首先要做到的是,发生问题的期间,可以对运行时进行观测。但是,在 top 都无法正常工作的状态下,lldb、promethues、log 之类的东西是根本无法正常工作的。在这种基本属于盲猜的状态下,唯一能进行的就是分析调用链、拆解程序、分段执行,用极小的模块尝试复现问题,然后一步一步慢慢缩小复现的范围,进而最终定位到问题。简而言之,经典的控制变量法,分而治之。

报 bug 的调用链非常简单,就是一个 rpc → rocksdb → response 的调用过程,相对来说,只是返回的数据稍微多一点,并没有其他异常情况。我尝试构建了一个这样的程序,用相同的 db 和相同的 rpc 参数,但直接写死调用,返回后序列化成 json。然后复现了,物理机假死后,任何操作都无法执行,但可以执行 ctrl + c,就可以直接退出程序,整个数据是 get_cells 接口查询 64w cell,可控制同时查询次数,在次数为 2 的时候,运行时内存占用达到了 4 g,但输出的 json 只有 400M 左右,将查询次数设置为 6 的时候,稳定复现问题,复现的机器内存上限是 8g,而且很容易看出,随着查询次数变大,运行时内存占用也是呈线性上升。

这里看上去是大内存占用/申请,导致了物理机假死,但尝试使用一个简单的循环申请内存不释放的程序,会被 oom kill 掉,而简化的问题程序,竟然会导致物理机假死,阻止了 oom 执行,或者说延时了 oom 执行,这是一个很神奇的程序。猜测是 io 调用被占满了,无法执行其他命令。

简化后的程序,唯一复杂的地方在 rocksdb,在这个查询过程中,它使用了 iterator 功能,根据官方的描述,iterator 在执行过程中,会将内容 pin 在内存中,包括 sst 文件,直到 iterator 销毁的时候才释放,这很可能是内存暴涨的原因,但经过一系列测试 + 代码查看,无法确认内存暴涨是这个原因,但也无法排除,至少循环调用 iterator 查询,得出数据后直接销毁,内存无变化。

对于这种问题,修复方案其实很简单,对相应的 rpc 调用进行数据量上的限制,就可以直接限制它的内存使用量,进而达到修复的目的,但找到核心问题也很关键。

拆(猜)程序(二)

为了确定是否是 iterator 释放延时导致的问题,我将测试程序的查询过程改成了分步查询,最后汇总的方式,从原来一次查询结束,变成了多次查询,会产生多个 iterator,但最后结果不变。如果是 iterator 延时释放的问题,那么多段小量数据,内存应当是平缓释放而不是线性增加。然而,测试结果是与一次查询内存占用一致,几乎没有变化,这不得不令人疑惑。

接着,我将查询目标从 get_cells 换成了 get_cells_capacity,查询过程一致,查询结果从 cell 结构变成了 u64 加和,惊奇地发现,get_cells_capacity 几乎不消耗内存,也就是说,大概率可以排除是 db 使用上的问题。

于是猜测是不是 get_cells 数据生成的时候,关联到了一些不必要的内存,导致数据占用的内存变得异常多。然后发现了一些问题:

impl From<packed::Bytes> for JsonBytes {
    fn from(input: packed::Bytes) -> Self {
        JsonBytes::from_bytes(input.raw_data())
    }
}
impl Unpack<Bytes> for packed::Bytes {
    fn unpack(&self) -> Bytes {
        self.raw_data()
    }
}

单看上面两个实现,其实都没有问题,但是加入下面 raw_data 实现之后,就会出问题(这里三个实现本身并没有问题):

pub fn raw_data(&self) -> molecule::bytes::Bytes {
  self.0.slice(molecule::NUMBER_SIZE..)
}

Bytes 的 slice 实现,是截取其中一部分,用 Arc 指向,相当于它使用了原始 Bytes 的一部分内存,但会 pin 住整个 Bytes 的所有数据不释放,这里可以看作是内存泄漏。

把内存泄漏的问题处理完之后,发现内存还是居高不下。为了确定数据真正要使用的内存,mock 了 64w cell 的数据结构,然后输出 json,发现运行中,内存占用就是 2g,而 json 输出是 200M。把输出数量变成 6,发现这次可以被 oom 瞬间 kill; 加上 db 操作(只查询不返回数据)之后,又会机器假死了,真的非常神奇。难道是 db 和 数据内存占用相互作用导致的问题?

拆(猜)程序(三)

我们已经拆到程序只有 mock 数据 + json 序列化输出 + db 查询但不返回数据了,接下来,尝试复现并加上每一步的 log,确认程序是在哪一步执行的时候卡住了。这个测试很轻易地发现,db 查询不卡,mock 数据不卡,最后一条日志出现在 json 序列化之前,同时这也是测试程序的倒数第二行代码。这就有意思了,难道是 json 序列化的问题?这是在猜问题的时候,基本可以被忽略的盲区。

我们又把 db 查询删掉了,只有 mock 数据和 json 序列化输出,发现十次里面有七八次会出现机器假死的情况,然后我们降低次数,并使用 jemalloc profiling 去抓运行时内存图,发现确实是 serde json 占用异常高。接着在 serde json 项目的 issues 中发现了这样一个 issue,我们的测试程序与该 issue 反馈的问题一致,都是需要消耗 10x 内存进行序列化。

结论

结论很明显,serde json 是罪魁祸首,它在序列化的时候用了十倍以上的内存,同时它的内存申请方式也是层层递进,少量多次的那种,但很神奇的是,oom kill 在这种情况下的响应被明显拖延了,导致了整个物理机上的僵死状态。

目前的修复方案因为兼容的问题,只是加上了可选的限制,不过我们强烈建议任何需要使用这个接口的节点都加上这两个限制,用来防止问题发生。至于修复 serde json 内存占用问题,从机制上来看似乎难度有点大,同时 serde json 几乎已经是社区唯一的序列化库了,暂时还没有替换的必要。当然,还有一种修复方式,就是直接返回 molecule 结构的数据,这个需要后续看看社区是否有这样的需求。

8 Likes

影响是在全节点上吗?

直接返回 molecule 结构的数据

如果能提供一个通用的molecule → json output的utility/package/example(生态常用的开发语言 ts/js, go)的话应该问题不大

开起了 indexer 的 ckb 全节点

1 Like