一次并发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)
    local session = silly_timeout(ms)         --silly_timeout 等价于 silly_timer_timeout
    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要小。

这也意味在有一个session在timeout之后立即就收到了expire消息。

于是我重新去看了一下silly_timer_timeout函数,我终于发现问题所在了。

在silly_timer_timeout时由于超时时间非常短的情况下。如果有以下步骤,就是必现的。

  1. silly_timer_timeout加入node N1, 在执行完unlock之后,silly_timer_timeout所在的线程T1突然被切换而暂停执行了。
  2. 这时silly_timer_update在线程T2执行了,它检查到N1已经达到了超时标准,于是将其关联的session用expire消息推送到lua线程并将N1释放(free)。
  3. 其他代码调用malloc重新分配到了刚刚释放N1的内存,并写入数据
  4. T1 重新唤醒被执行。silly_timer_timeout返回了错误的session, 但是silly_timer_update却推送了正确的session.

我在unlock之后加入了usleep(5000)之后,不一会,bug就重现了。


我复盘了一下整个bug分析流程,我发现整个思路都没有什么大问题。

惟一有问题的是,我做了一个错误的假设B1。

B1 应该被修改为,返回了一个无效的session(重复的session同样是无效的session)。

之所以我做了错误的B1假设,是因为潜意识告诉我,silly_timer_timeout返回的session不可能问题了。我在一个错误的假设上做了各种推理。

这次经历告诉我,当相关代码出bug时,一定要忘记所有背景知识,仅对出问题的相关代码进假设(一切皆有可能)。

然后再根据相关信息进行逐个排查。

即使如此,打破思维定式,真的很难 ^_^!



发表评论