51

【踩坑笔记】一次加锁和超时控制引起的交通事故

 5 years ago
source link: https://studygolang.com/articles/13872?amp%3Butm_medium=referral
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

问题回顾

线上发现流量接入层好像扛不住,一直在被 OOM,并且客户出现大面积的超时。但是流量并没有打到后端的业务层。

在回滚代码,并且加机器之后,问题被解决了。

问题定位与解决

首先,怀疑是流量过大引起的。但是奇怪的点在于大部分流量没有打到业务层。通过分析流量接入层的日志,我们发现 有两个相邻日志输出的时间间隔比较长 。而这两条日志输出之间正是有回滚的代码。所以,我们将问题定位的方向转移到了代码层面。

但是,线下压测过程中,并没有发现类似的严重耗时问题,(怀疑是测试 case 没有覆盖到)。于是,先人工 Review 一遍变动的代码。我们发现,有一个代码片段是加锁的,代码如下所示( golang 省略部分细节):

// key1
    if val, exist := rateMap.Load(key1); exist {
        return true, val.(*RateLimit).Taken(count)
    }

    Lock.Lock()
    defer Lock.Unlock()
    if mapC, exist := RateLimitC[flag1]; exist {
        for _, val := range mapC {
            if key1_ok {
                rateLimit := NewRateLimit(val.Qps)
                rateLimit.Create()
                rateMap.Store(key1, &rateLimit)
                return true, rateLimit.Taken(count)
            }
        }
    }

    // key2
    if val, exist := rateMap.Load(key2); exist {
        return true, val.(*RateLimit).Taken(count)
    }

    for _, val := range RateLimitC[flag2] {
        if key2_ok {
            rateLimit := NewRateLimit(val.Qps)
            rateLimit.Create()
            rateMap.Store(key2, &rateLimit)
            return true, rateLimit.Taken(count)
        }
    }

这是一段 QPS 限流的逻辑,内部实现利用了令牌桶算法,(先忽略有待优化的逻辑,我们来看为什么会出现问题)

代码的大概意思是:

如果用 key1 获取到了 token,就直接返回;否则,加锁,看是 map 里是否有 flag1 代表的限流信息,如果有,则判断是否有符合 key1 条件的,如果有,则走正常获取 token 逻辑;如果没有,则尝试用 key2 获取 token,(下边逻辑类似 key1)

问题就出在线上大部分情况需要用 key2 来获取 token,所以大部分请求都会进入加锁区域。如果只是一个加锁,应该很快就能处理完,但是会有堆积性的耗时呢。

我们来看一下 val.(*RateLimit).Taken(count) 的实现:

func (this *RateLimit) Taken(count int) error {
    timer := time.NewTimer(time.Duration(count) * TimeDuration)
    defer timer.Stop()

    for i := count; i > 0; i-- {
        select {
        case <-this.BucketCh:
        case <-timer.C:
            return errors.New("not get bucket")
        }
    }

    return nil
}

里边有个超时机制,如果限定时间内没有获取到 token,则返回错误。

那么,现在的问题是,所有走通过 key2 获取 token 都会在加锁的区域串行通过,那么,当没有立即获取 token 的请求,阻塞在计时器的时候,其他等待锁的请求都会阻塞在加锁的阶段,直到上一个请求超时,或者获取到 token,他才能获得锁。

换句话说,这条路是一个单行道,一次只能有一人通过,这个人还经常卡在收费站口,那么后边来的人就可能会越积越多,等待的时间越来越长,最后把路都给压垮了。

总结

像这种错误,想到之后是很容易复现的,而且只要满足条件,这个 bug 必现。

反思:

case

另外,这种耗时问题,可以在线下用 go 官方的 pprof 包,查看一下程序的耗时情况,也是可以发现的。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK