一次并发Bug

最近碰到一个bug, 约7天发生一次，历时3周才找到问题并修复。

在找到bug并修复后，我仔细反思了一下。

我发现不仅这个bug是并发bug的一个典型，修复bug的过程也是直击我的弱点。

下面记录一下整个过程。

最近突然想对我的网络框架做一次RPC浸泡测试。

写了一段代码，开了6000个客户端，去并发RPC请求，服务端收到RPC之后会随机10~2500ms 延时之后再返回。丢到我的VPS上之后，也没在意，过了两天就忘记这回事了。

过了大概一周，我突然想起来我还有一个浸泡测试在跑着呢，就上去看了一下log.

令我意外的是，网络和rpc没有出现bug，定时器出现Bug了。

就这样一边加log等重现，一边看代码，在历时3周后终于靠看代码修掉了。

定时器相关代码大概如下：

--core.lua（run in thread1)

function core.timeout(ms, func) local co = cocreate(func)

--silly_timeout 等价于 silly_timer_timeout local session = silly_timeout(ms)

sleep_session_co[session] = co sleep_co_session[co] = session

return session

end

local MSG = {}

function MSG.expire(session, _, _) local co = sleep_session_co[session] assert(sleep_co_session[co] == session) sleep_session_co[session] = nil sleep_co_session[co] = nil wakeup_co_queue[#wakeup_co_queue + 1] = co

end

//silly_timer.c

uint32_t silly_timer_timeout(uint32_t expire){ struct node *n = newnode(); if (unlikely(n == NULL)) { silly_log("silly timer alloc node failed\n"); return -1; } lock(T); n->expire = expire / TIMER_RESOLUTION + T->ticktime; assert((int32_t)(n->expire - T->expire) >= 0); add_node(T, n); unlock(T); return n->session;

}

// run thread2

void silly_timer_update()

{

//检查所有struct node, 是否超时

//如果超时，则向Lua层抛出expire消息

//然后将node结点Free掉

//在Lua层收到expire消息后，会调用MSG.expire函数

}

发现bug时，是发现在MSG.expire函数的第二行assert失败了。

这时我就告诉自己，柯南君的名言“排除一切不可能，剩下的再不可能也是真相”。

即然assert失败了，那只有三种可能。

A1. co 为 nil, 这时sleep_co_session[co]为nil A2. co 不为nil 且sleep_co_session[co] 为nil A3. co 不为nil 且 sleep_co_session[co]不等于session

我检查了一下代码，发现sleep_session_co 和sleep_co_session都是一起操作的，因此我将A2排除了。

为了进一步排除A1和A3, 我在MSG.expire加了点log，当assert失败时，打印一下session和co的值。

过了几天后确定是A1.

而导致A1产生的可能情况有以下几种可能：

B1. silly_timer_timeout返回了两个相同的session B2. silly_timer_update 对同一个session返回了2次 B3. silly_timer_update 返回了一个陌生的session

我查了一下rpc client端的log,我发现在相同的时间确实有一次rpc请求失败了，排除了B2.

如果是情况3, 那就代表silly_timer_update时返回的是脏数据，我查看了silly_timer.c中的代码，发现node->session只有在newnode时被赋值，其他情况并没有被改动过。因此我将B3排除了。

现在就剩下B1，出现B1 有两种可能。

C1. session回绕了 C2. 在++session时有并发问题出现了某种竞争

于是，我在session回绕和session每增加1000时，分别打印了一行log。以期望可以在下次重现时，获得一些有用的信息。

再次出现之后，我发现session并没有回绕，而session每增加1000打印的log似乎对我并没有什么帮助。

我开始把矛头对准C2分析。但是我反复检查，以我现有的知识来讲，session都不可能存在并发问题。

线突然断了，我知道一定是我哪里弄错了，但是我思维已经造成了定式。反复思考也没看到哪里有问题。

之后，每天打开电脑第一件事，就是去看一遍之前发生过的log和代码，以便突然有点灵感。

在过了大约7天之后，我突然发现，session每增加1000时的log L1和assert失败时的log L2发生在同一秒，而出错的session比L1中打印出来的session要小。