【踩坑笔记】一次加锁和超时控制引起的交通事故
fevin · · 2045 次点击 · · 开始浏览问题回顾
线上发现流量接入层好像扛不住,一直在被 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 包,查看一下程序的耗时情况,也是可以发现的。
有疑问加站长微信联系(非本文作者)
入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889
关注微信- 请尽量让自己的回复能够对别人有帮助
- 支持 Markdown 格式, **粗体**、~~删除线~~、
`单行代码` - 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
- 图片支持拖拽、截图粘贴等方式上传
收入到我管理的专栏 新建专栏
问题回顾
线上发现流量接入层好像扛不住,一直在被 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 包,查看一下程序的耗时情况,也是可以发现的。