“我报名参加金石计划1期挑战——瓜分10万奖池，这是我的第n篇文章，点击查看活动详情”

系统延迟两三事（一）

存储系统长尾延迟、抖动、突然变慢令人非常头疼。本文记录了一些在存储系统上对延迟定位、调优、彻底解决的案例。

我们需要怎样的监控组件

可靠系统应该有完善的统计监控，特别是一个存储服务，涉及的组件数十个，每个组件有数百项监控指标，当对这些监控指标了然于胸之时，便是掌握其之日。常见的监控指标有平均值，最大值，中位数，P99直方图，我们对监控组件的需求很明确：

支持多线程环境下计数
atomic count是不够用的，具体来说多核下atomic可能会cacheline bouncing1
使用简单，一个类支持多种指标计算、输出
可视化，支持同比、环比

brpc的bvar做了较好的抽象和良好性能实现，我们大量使用了bvar::LatencyRecorder，专用于记录延时和qps的变量。输入延时，平均延时/最大延时/qps/总次数，我们使用bvar+clickhouse+grafana搭建了完善的监控统计，帮助诊断了非常多的系统问题。

案例一：rocksdb seek慢了1万倍

如上图所示，某服务在rocksdb存储了大量较短TTL的数据，该数据结构即是redis hash的增强版rocksdb实现：支持field级别的TTL。该结构使用两层column family:meta cf和data cf，但也有一些潜规则：

每个cf rocksdb 会有自己的compact周期
data cf 发现TTL到期即将自己删除
rocksdb的compact::filter函数内不允许写，否则会发生死锁
meta cf 需要seek 发现data cf 为空时才能删自己

然而上线后我们发现手动compaction极慢，下图，一分钟只有100多次seek！这是否会直接导致了业务写stall? 赶紧下线回滚！

打开rocksdb log，cat rocksdb_log |grep -v "SUM : 0" |grep -v "COUNT : 0"，下面这种日志着实令人吃惊：

总结下来，确实反常：

该服务在线响应非常快，其中请求必然包括大量seek
日常seek并没有这么慢，为何我们的compaction P50延迟到了600ms？
虽然在compaction filter中关闭了fill_cache，但我们的nvme io并不慢
iotop 没有大量的read io
google perf发现CPU大量耗费在rocksdb::parserUserKey，看起来一切正常

继续看rocksdb 日志，发现了如下计数器：

rocksdb release note写得很清楚：

Add a DB stat,NUMBER_ITER_SKIP, which returns how many internal keys were skipped during iterations (e.g.due to being tombstones or duplicate versions of a key).

原来data cf累计了大量tombstone，或者业务对同个key做了大量的覆盖更新（后来证明是multi version导致），rocksdb并不会主动激进地compact这些墓碑，除非你手动compact。这直接导致我们在手动compact时，filtering 100个meta key ，我们需要skip 446872892次才能确认是否找到这个前缀！更尴尬的是，我们使用下面的代码做compaction：

解决方案：

手动compaction，消除tombstone
将上面的manual compaction顺序换一下，先compactdata cf，而后meta cf

观察一次rocksdb日志，rocksdb.db.seek.micros P50性能优化到18us，rocksdb.number.iter.skip 降到2608，第二次降到0。

观察监控系统，现在我们的meta filter性能飙升：

系统每隔10分钟延迟抖增

某系统使用raft作为replicate协议，上线后发现被调抖动非常有规律，遇到这种现象我们通常都不慌，周期性的问题最好定位了。检查系统定时器，发现snapshot定时器恰好为10分钟。然而想要完美解决却并不简单：

raft 串行apply导致卡顿

打开源码，直接定位到do_snapshot，发现里面不过是做调用了rocksdb::create_checkpoint，很容易想到：raft 是串行apply所有task，包括do_snapshot，而do_snapshot直接导致了后续请求卡顿。

为什么raft 必须串行apply，do_snapshot可以异步吗？
熟悉rocksdb的朋友知道，rocksdb::create_checkpoint应该挺快，然而监控看到长尾甚至高达5s！

checkpoint为什么这么慢

首先查看rocksdb checkpoint源码，路径如下：

CreateCheckpoint
    =>CheckpointImpl::CreateCustomCheckpoint
        =>GetLiveFiles
            =>AtomicFlushMemTables

如下图，在CreateCustomCheckpoint，rocksdb提供两种回调

link_file_cb，如果rocksdb发现源目录与目标目录是同个盘，使用link模式
copy_file_cb，checkpoint目标盘与源目录不同，使用这个模式

反复测试，我们确实走了link而非copy路径，linux hard link一些文件这么慢？修改rocksdb CreateCustomCheckpoint，使用bvar添加了许多监控指标，最终发现2个耗时大户:

create checkpoint时，会flush！这里有大量的写磁盘操作，如果raft做snapshot时，rocksdb memtable数据较大，将会直接导致卡顿。
hard link也可能是耗时大户，当sst文件成百上千时，逐个sst create link也是非常慢的，至于sst文件暴增碎片化问题，值得另一个文章来写。

raft 是否可以异步do_snapshot

先考虑为什么braft，jraft没有这么做，我们来看看raft 流程：

其中几个index的含义：

snapshot last include index，raft状态机快照目录包含的最大log index，重启时，通常从该index+1开始执行
commited index，这是状态机真正执行过的index。

applied index，上图没有画出来，raft执行过的最大log index，实际等于commited index
uncommited index，待复制到majority节点的log

梳理下上图中，raft状态机启动流程：
首先从snapshot目录下载快照到运行目录（step1)，根据snapshot last include index，日志从log5开始apply到状态机。
raft不断append log到磁盘，同时replicator不断将该日志发送2个follower(N=3)
其中一个follower回复到leader，黄色部分开始应用到状态机（step2）
定时线程N秒后将状态机已applied部分真正持久化（step3)，并记住这一次的index，它便是下一次重启的snapshot last include index(log4）

注意step3中，我们要求snapshot是log的apply后的一个完整集合。也即是说，每一条log只能执行一次。do_snapshot时，我们首先记住snapshot last include index = current index，如果异步do_snapshot，写到状态机的数据很有可能比current index大，而下次重启时，我们仍会从snapshot last include index开始执行：想象下，如果log的命令是update+1:

下一次重启时，update+1命令会又做一遍！因此我们不能简单地将do_snapshot异步化。必须让raft log "exactly once"执行，才可能异步化do_snapshot.

解决方案

前面提到，让raft状态机过滤掉已经执行过的raft log，才有可能做到异步化do_snapshot。已经执行的raft log(commited index)也就是applied Index存下来，下次重启时，提前return掉，不就相当于"exactly once"了嘛！

raft 作者更新了论文[3]，也就是说applied index是一个正路：

Figure 3.1 (cheatsheet): Although lastApplied is listed as volatile state, it should be as volatile as the state machine. If the state machine is volatile, lastApplied should be volatile. If the state machine is persistent, lastApplied should be just as persistent.

解决方案呼之欲出：

让状态机幂等，我们在每个key上添加一个uuid（即current index），update+1操作重放多几次都没问题，do_snapshot可以彻底异步化

缺点：该方案缺点是每次重启后，仍要一次读一次key，解析正确的last applied index是否被snapshot应用过，以决定是否跳过，耗损较大，实际上上图中绿色部分，都是被曾经applied过，但未及时do_snapshot存到快照的部分，重启一次，需要重新执行一次，非常浪费，而且可能追不上黄色部分，亦或造成host机器瞬时抖动卡顿。

让applied index独立持久化，例如BaikalDB做法是apply后让业务数据和applied index在一个rocksdb 事务上持久化，而后直接skip掉，代码如下：


void Region::do_apply(int64_t term, int64_t index, const pb::StoreReq& request, braft::Closure* done) {
    if (index <= _applied_index) {
        if (get_version() == 0) {
            DB_WARNING("this log entry has been executed, log_index:%ld, applied_index:%ld, region_id: %ld",
                       index, _applied_index, _region_id);
        }
        return;
    }
    .......
}

缺点：该方案在重启时，不必读状态机以确认是否需要skip，可以直接在启动前获得applied index，raft提交时直接丢掉小于它的index，避免了重放导致的瞬时抖动，但rocksdb事务接口会慢个20%。但这始终不是我想要的最终形态。

让applied index持久化，但不使用事务接口，我们允许applied index滞后一点点，使用rocksdb flush listener监听applied index。重启时，像BaikalDB那样skip掉一些log即可。

系统延迟两三事(一)