在写这篇文章前，我突然想到以前流行了一段时间的服务器面试题：当一个BUG只有几百万分之一的概率会出现，怎么办？这个问题在这个BUG里只是毛毛雨而已，因为这次的BUG的出现概率是夸张的三亿分之一。
我在好几年前自己开发了一个用于服务器进程间通信的框架，libatbus，以前用在了客户端的模块隔离的通信心痛中。并且现在开始正式用于服务器。但是前两天看了一下服务器的日志，发现了比较奇怪的-202错误。
这个问题本来是已知的，在当时通信系统设计并且做测试的时候就发现了这个问题，详见关于BUS通信系统的一些思考（二）。后来经过几次设计细节的调整，具体的实现可这篇文章有一些变化，但是主要原理是一样的。
因为在benchmark时BUG的发生概率在大约三亿分之一，并且在单进程多线程模式下没有发现过这个错误。并且后来在增加了自动重试之后很长时间都没出现过问题，所以当时认为可能是跨进程原子操作的时候可能内存屏障有些问题导致的。也没太在意，毕竟服务器本身也有一层超时保护，而且还得保持在高压力上才会发生,三亿分之一的发送错误实在微不足道。
但是我们服务器程序开发阶段，压力不可能高，又出现这个问题，说明我之前的猜测是不对的（果然猜测是大忌啊）。虽然发生频率很低，但是通信服务是一个非常基础的东西，这就需要关注下保证更高的可靠性了。
写工具，分析问题
为了更深入地了解到底是什么情况，因为发生概率十分地低，所以很难抓到现场，第一步只能是写个小工具导出libatbus共享内存通道的统计数据，然后发现有一些奇怪的计数。
summary:
channel node size: 128
channel node count: 123331
channel using memory size: 16777112
channel available node number: 123330
configure:
send timeout(ms): 4
protect memory size(Bytes): 123264
protect node number: 963
write retry times: 4
read&write:
first waiting time: 0
read index: 51896
write index: 51896
operation sequence: 1064070
stat:
bad block count: 22
bad node count: 3110
timeout block count: 18
read&write:
first waiting time: 0
read index: 51896
write index: 51896
operation sequence: 1064070
在几个月的运行中，这种低负载的情况下，竟然出现了22次错误数据和18次timeout。这显然不太可能于是需要进一步地完善工具提供更多的信息。收集错误的数据。
第一个BUG: 发生频率-三亿分之一
第一个BUG，其实是review了一遍代码发现的。还是比较2B的BUG。
原来的逻辑里有一段功能是为了防止某些发送端进程在写出数据时崩溃，为了在这种情况下接收端需要能够自动修复并跳过错误数据。但是接收端并不知道写出端是崩溃了还是正在写出，所以有一个遇到未完成写出的节点时的超时判定，在超时后认为出现错误而强制跳过。原来有BUG的代码如下：
// 容错处理 -- 未写入完成
if (!check_flag(node_head->flag, MF_WRITEN)) {
uint64_t cnow = (uint64_t)clock() * (CLOCKS_PER_SEC / 1000); // 转换到毫秒
// 初次读取
if (!channel->first_failed_writing_time) {
channel->first_failed_writing_time = cnow;
ret = ret ? ret : EN_ATBUS_ERR_NO_DATA;
break;
}
uint64_t cd = cnow > channel->first_failed_writing_time ? cnow - channel->first_failed_writing_time
: channel->first_failed_writing_time - cnow;
// 写入超时
if (channel->first_failed_writing_time && cd > channel->block_timeout_count) {
read_begin_cur = mem_next_index(channel, read_begin_cur, 1);
++channel->block_bad_count;
++channel->node_bad_count;
++channel->block_timeout_count;
channel->first_failed_writing_time = 0;
continue;
}
// 未到超时时间
ret = ret ? ret : EN_ATBUS_ERR_NO_DATA;
break;
}
这里面认为first_failed_writing_time为0则是第一次出错，然后下一次recv的时候如果未超时则认为是写出端数据没写完而返回无数据，但是超时后返回错误并且跳过错误数据块。
这里的问题就出在时间计算上，那里不应该是乘，而应该是除。在linux里，CLOCKS_PER_SEC / 1000的值是1000，那么cnow变成了1000倍的clock()。然后还有个问题是超时时间不是channel->block_timeout_count，而且应该是，channel->conf.conf_send_timeout_ms。
所以在这两个BUG的夹击下，只要是连续第二次进入判定超时阶段，十有八九会被判定为超时。之所以发生概率三亿分之一，是以为其他情况下在第二次执行尝试读取数据时，写出端都把数据写完了，那么MF_WRITEN就会被标记。所以这里必须是两次连续读期间写出端还没写完才行，所以发生频率才很低。
所以修复完以后，代码如下：
// 容错处理 -- 未写入完成
if (!check_flag(node_head->flag, MF_WRITEN)) {
uint64_t cnow = (uint64_t)(clock() / (CLOCKS_PER_SEC / 1000)); // 转换到毫秒
// 初次读取
if (!channel->first_failed_writing_time) {
channel->first_failed_writing_time = cnow;
ret = ret ? ret : EN_ATBUS_ERR_NO_DATA;
break;
}
uint64_t cd = cnow > channel->first_failed_writing_time ? cnow - channel->first_failed_writing_time
: channel->first_failed_writing_time - cnow;
// 写入超时
if (channel->first_failed_writing_time && cd > channel->conf.conf_send_timeout_ms) {
read_begin_cur = mem_next_index(channel, read_begin_cur, 1);
++channel->block_bad_count;
++channel->node_bad_count;
++channel->block_timeout_count;
channel->first_failed_writing_time = 0;
continue;
}
// 未到超时时间
ret = ret ? ret : EN_ATBUS_ERR_NO_DATA;
break;
}
经过上面的修复，继续跑debug版本的benchmark，连续2小时都没再出现任何错误，但是切到**RelWithDebInfo（-O2 -g -ggdb）**后大约平均十亿分之一的概率出现了错误记录。
第二个BUG: 发生频率-十亿分之一到百亿分之一
这次已经没有这种很傻的BUG了，并且错误出现率进一步降低。这时候发现之前的错误信息转储不太能展示错误到底出现在哪个流程里。于是乎review完写出和接收端代码没有发现问题后我就给通道数据导出增加了更多的信息。这个信息后来证明很有价值。当时查出问题所在的日志我没保存，但是在我区分了各个状态的错误码后我发现了两个问题。
第一个问题：并没有出现超时、校验码错误、长度校验错误、写重试和写错误的情况下，单单出现了和节点错误计数。（十亿分之一）
这个而只有在一个流程下没有其他计数只有节点错误计数。那就是如下位置:
read_end_cur = read_begin_cur; // read_begin_cur是通过channel->atomic_read_cur.load()获取的
if (read_begin_cur == write_cur) {
ret = ret ? ret : EN_ATBUS_ERR_NO_DATA;
break;
}
volatile mem_node_head *node_head = mem_get_node_head(channel, read_begin_cur, NULL, NULL);
// 容错处理 -- 不是起始节点
if (!check_flag(node_head->flag, MF_START_NODE)) {
read_begin_cur = mem_next_index(channel, read_begin_cur, 1);
node_head->flag = 0;
++channel->read_bad_node_count;
continue;
}
这里本意是其他位置发现了错误，跳过起始节点，然后在主循环里计数并跳过所有的错误数据节点。但是莫名奇妙在没有检测到错误起始节点的情况下直接进了这个流程，就比较诡异了。
后来我就再分析了发送端代码，结果发现了问题所在。
// 查找可用数据节点阶段
while (true) {
read_cur = channel->atomic_read_cur.load();
// std::atomic_thread_fence(std::memory_order_seq_cst);
// 要留下一个node做tail, 所以多减1
size_t available_node = mem_get_available_node_count(channel, read_cur, write_cur);
if (node_count > available_node) {
return EN_ATBUS_ERR_BUFF_LIMIT;
}
// 新的尾部node游标
new_write_cur = mem_next_index(channel, write_cur, node_count);
// CAS
bool f = channel->atomic_write_cur.compare_exchange_weak(write_cur, new_write_cur);
if (f) break;
// 发现冲突原子操作失败则重试
}
// 数据缓冲区操作 - 初始化
void *buffer_start = NULL;
size_t buffer_len = 0;
mem_block_head *block_head = mem_get_block_head(channel, write_cur, &buffer_start, &buffer_len);
memset(block_head, 0x00, sizeof(mem_block_head));
// 数据缓冲区操作 - 要写入的节点
{
block_head->buffer_size = 0;
volatile mem_node_head *first_node_head = mem_get_node_head(channel, write_cur, NULL, NULL);
first_node_head->flag = set_flag(0, MF_START_NODE);
first_node_head->operation_seq = opr_seq;
for (size_t i = mem_next_index(channel, write_cur, 1); i != new_write_cur; i = mem_next_index(channel, i, 1)) {
volatile mem_node_head *this_node_head = mem_get_node_head(channel, i, NULL, NULL);
assert((char *)this_node_head < (char *)channel + channel->area_data_offset);
// 写数据node出现冲突
// 写超时会导致this_node_head还是之前版本的数据，并不会被清空。所以不再恢复 operation_seq
// if (this_node_head->operation_seq) {
// return EN_ATBUS_ERR_NODE_BAD_BLOCK_WSEQ_ID;
// }
this_node_head->flag = set_flag(0, MF_WRITEN);
this_node_head->operation_seq = opr_seq;
}
}
block_head->buffer_size = len;
上面的代码先通过原子CAS操作获取到可用的内存块，然后对节点头设置标记位，并且在第一个节点设为MF_START_NODE。问题就在这里，CAS操作是先进行的，然后第一个节点设为MF_START_NODE在后。虽然这两个操作的距离很近，可能只涉及几十条指令。但是这段时间内如果进程被切出，然后读进程读到了CAS之后的写游标，又发现第一个节点不是MF_START_NODE的时候，就被判为错误节点了，于是乎才丢失了数据。这个问题处理起来比较麻烦，因为不能破坏对真正错误数据的容错处理，还要能正确处理这种情况。
最终我分析了一下流程，在读取端获取了新的写游标位置后，可能写出端处于移动了atomic_write_cur，但是还没有写出MF_START_NODE的情况。所以情况列举如下:
- MF_START_NODE | MF_WRITEN: 数据块已写完
- MF_WRITEN: 节点容错
- MF_START_NODE: 是起始节点但是数据未写完（也可能是发送端在写出过程中崩溃）
- 空: 移动游标后尚未设置MF_START_NODE，这个出现概率非常低，但是也会出现。（也可能是发送端在写出过程中崩溃）
由于MF_START_NODE和空都是无法判定是没写完还是写出端崩溃的，所以都要走超时检测逻辑。
但是如果被判定超时并且写出端只写出了部分节点的的MF_WRITEN这时候剩下的节点的flag都会是空。
如果这些都通过超时机制判定，则最多可能等待消息长度*超时判定时长/节点长度，默认设置是最少2秒钟。
所以这里需要特别处理下，当进入超时流程后，所有非MF_START_NODE并且operation_seq相等的节点也应该视为错误。
注意上面这个流程只能在超时流程中进行，因为其他错误流程可能第一个数据块错误，但是紧接着的第二个数据块处于正在写出的状态而没有设置
MF_START_NODE和operation_seq。我们的operation_seq取值范围是uint32，所以max(uint32)节点长度（默认是500GB）以内的通道里operation_seq*不会重复
我们的数据通道不可能使用这么大的内存，所以加上operation_seq后能尽可能地消除空数据快的超时影响。
第二个问题：更诡异的数据被复写（百亿分之一）
重点日志如下:
shm_recv error, ret code: -202. start: 101398, end: 101403
Summary:
channel node size: 128
channel node count: 123331
channel using memory size: 16777112
channel available node number: 12578
Configure:
send timeout(ms): 4
protect memory size(Bytes): 16384
protect node number: 128
write retry times: 4
IO:
first waiting time: 0
read index: 101403
write index: 88696
operation sequence: 4023560795
Statistics:
write - check sequence failed: 0
write - retry times: 0
read - bad node: 16
read - bad block: 0
read - write timeout: 0
read - check block size failed: 0
read - check node count failed: 1
read - check hash failed: 0
Debug:
last action - channel: 0x7f9291997000
last action - begin node index: 101398
last action - end node index: 101403
......
Node index: 101398 => seq=4023547849, is start node=No, is written=No, data(Hex): 3807000000000000fdeb7cfc0000000000670100b0b0b0b0
Node index: 101399 => seq=4023547849, is start node=No, is written=No, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101400 => seq=4023547849, is start node=No, is written=No, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101401 => seq=4023547849, is start node=No, is written=No, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101402 => seq=4023547849, is start node=No, is written=No, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101403 => seq=4023533496, is start node=Yes, Data Length=616, Hash=872284744, is written=Yes, data(Hex): 68020000000000004802fe3300000000fe66010033333333
Node index: 101404 => seq=4023533496, is start node=No, is written=Yes, data(Hex): 333333333333333333333333333333333333333333333333
Node index: 101405 => seq=4023533496, is start node=No, is written=Yes, data(Hex): 333333333333333333333333333333333333333333333333
Node index: 101406 => seq=4023533496, is start node=No, is written=Yes, data(Hex): 333333333333333333333333333333333333333333333333
Node index: 101407 => seq=4023533496, is start node=No, is written=Yes, data(Hex): 333333333333333333333333333333333333333333333333
Node index: 101408 => seq=4023547849, is start node=No, is written=Yes, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101409 => seq=4023547849, is start node=No, is written=Yes, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101410 => seq=4023547849, is start node=No, is written=Yes, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101411 => seq=4023547849, is start node=No, is written=Yes, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101412 => seq=4023547849, is start node=No, is written=Yes, data(Hex): b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0b0
Node index: 101413 => seq=4023547850, is start node=Yes, Data Length=1864, Hash=938159398, is written=Yes, data(Hex): 4807000000000000262deb3700000000ff66010027272727
节点101398已被跳过，所以MF_START_NODE标记被清理了，但是在出错时这里是其实节点。这个数据环境是三进程写，一进程读，通道长度16MB，超时判定4ms。
出错的结果是有一块数据被复写而丢失了。
错误数据在 Node index: 101398 处。中间被插入了Node index: 101403。
插入偏移量等于Node index: 101403的长度。怀疑是compare_exchange_weak在成功后内存未接受内存屏障进cache，并且返回失败，在下一次操作直接成功。
另外发现Node index: 101403的操作序号远低于Node index: 101398。开始分析认为可能是进程fe660100被切出，超时时间后才切回。导致前一次写数据覆写了后面的。但是这种情况应该先会被判定为缓冲区不足，而不是直接覆写。如果是接收端进入了超时检测分支，那么会有超时计数。但是包括后面几小时后的数据，超时计数都一直是0。所以排除了这种情况。
由于 http://en.cppreference.com/w/cpp/atomic/atomic/compare_exchange 里建议除非涉及数据表示多重含义或者附带对齐或数据切割，否则建议使用compare_exchange_strong。所以改成了compare_exchange_strong。可能是平台里原子操作的缓存逻辑问题所致。这篇文档里也说了compare_exchange_weak的情况下某些成功的行为会类似失败所以保险起见换成了compare_exchange_strong。而且后来压力测试也没发现性能有下降，所以就保持这样了。
顺带一点点小优化
这次BUG也查了挺久，加上移入了一些其他依赖库的一些小细节功能，所以随手加上了一些小优化。
- cmake的环境配置不再使用加编译宏的形式，而是configure(detail/libatbus_config.h.in)文件。这样如果移植给其他模块使用可以直接用生成好的头文件，保持配置一致。
- 很多地方都是在冲突时才有分支流程，这些地方加了一些likely和unlikely,已辅助编译器进行编译优化。
- 完善导出共享内存通道数据的小工具，原来输出的可读性稍微差一点。
- 因为是内存操作，增加了一些volatile。但是测试的时候未见性能下降，所以为保证正确，就留着了。这样能保证更快速的内存同步。
- 压力测试工具实现了更严格的数据校验，保证数据完全可预测然后精确校验数据。
新的稳定性测试
在上面的修复完成后我又进行了一整天的benchmark，环境仍然是三进程写，一进程读，通道长度16MB，超时判定4ms。最后的log如下：
[ RUNNING ] NO.1450 m
[ RUNNING ] recv(93055489089 times, 88395 GB) recv err 0 times, data valid failed 0 times
Summary:
channel node size: 128
channel node count: 123331
channel using memory size: 16777112
channel available node number: 1775
Configure:
send timeout(ms): 4
protect memory size(Bytes): 16384
protect node number: 128
write retry times: 4
IO:
first waiting time: 0
read index: 117979
write index: 116075
operation sequence: 2877148690
Statistics:
write - check sequence failed: 0
write - retry times: 0
read - bad node: 0
read - bad block: 0
read - write timeout: 0
read - check block size failed: 0
read - check node count failed: 0
read - check hash failed: 0
Debug:
last action - channel: 0x7f5688d7b000
last action - begin node index: 118300
last action - end node index: 118301
这里的性能指标低于文档里说示的结果，是因为这并不是单独对吞吐量和QPS的压力测试，发包的数据量比较大，范围是8B-2KB平均是1KB，所以QPS只有一百万多一点点，吞吐量也只是1GB/s多一点。但是实际性能并没有下降，因为改完之前这个数据包范围的数据也差不多是这样。当然以后有空还是可以重跑下压力测试。
最重要的是，可以看到一整天的满负载执行后，并没有出现一次错误。我们这次的BUG修复就算圆满达成了。