问题回顾
线上发现流量接入层好像扛不住,一直在被 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
,尽量可以自己覆盖到; - 如果只看锁的部分,不觉得有什么问题,但是跟上下文结合起来,问题显而易见(lock + timer);
另外,这种耗时问题,可以在线下用 go
官方的 pprof
包,查看一下程序的耗时情况,也是可以发现的。