您的位置:首页 > 编程语言 > Go语言

golang 高频服务延时抖动追因

2019-11-21 07:09 2971 查看

一,背景

策略组同学反馈有个服务上线后 redis 写超时非常严重,严重到什么地步呢,写redis 毛刺超过100ms! 而且不是随机出现,非常多,而且均匀,导致整个接口超时严重。因为用的redis 库是由我们组维护,所以任务落我们组小伙伴头上了。

这个项目有非常复杂的业务逻辑,有密集型io(调度问题)+定时任务(cpu问题)+常驻内存cache(gc问题),频繁访问redis,在定时逻辑中,业务逻辑需要一个request 可能达到上千次redis Hmget+get(先不讨论合理性)。 背景比较复杂, 是个golang 服务,接口延迟要求百ms级。

go version : 1.8,机器是8核+16G 容器,没有开runtime 监控,redis 的同事初步反馈没有slowlog。因为rd 也追了很久,到我们这边来的时候,redis 的超时指标监控已经给我们加了。

redis get 接口的耗时监控显示如下,因为高频请求,大部分耗时是小于10ms 的,但是这毛刺看着非常严重,是不可忍受了。

系统cpu问题比较严重,抖动非常大,内存并没有太大问题,但是占用有点大,比较有意思的事,因为用了local-cache,其实,我们刚开始以为是local-cache 导致的gc引起的。

因为没有加runtime 监控,其他信息暂不可知。

二,解决思路

因为追查接口毛刺比较复杂,我们的原则是不影响业务的情况下,尽量少上线的将业务问题解决。

我们初步给了个追查思路:

第一,首先排查是不是网络问题,对redis slowlog(redis 本身自带监控);

第二, 本地抓包,看日志中redis 的get 时间跟真实网络的时间是否对的上(抓包最可靠);

第三,对机器负载,是否对的上毛刺时间(cpu 资源不够,调度不过来毛刺也正常);

第四,查redis sdk,这库我们维护的,看源码,看实时栈,看是否有阻塞(sdk 用了pool,sdk 本身也要压测下);

第五,查看当前的gc pause ,看gc stw 时间是否影响redis(go 1.8 gc 性能比1.10-1.12 差很多);

第六,抓trace ,看调度时间和调度时机是否有问题(并发协程数,GOMAXPROCS cpu负载都会影响调度);

整个分析下来,只能用排除法了。

三, 现场分析

3.1 网络分析

因为服务的并发量比较大,其实查起来非常耗时。

  • 1, redis slowlog 本身是正常的。这里类似类似redis, redis 有SLOWLOG。这里感谢redis 团队的支持。

  • 2,我们该抓包了,将日志里的key 跟tcpdump 的key 对起来。因为并发量非常大,tcpdump 出来的数据简直没法看,这里我们线上dump,线下分析。

tcpdump 抓了几分钟时间。grep 日志里超时的case, 例如key 是rec_useraction_bg_2_user_319607672835 这个key 显示126ms, 但是wireshark 显示仅仅不到2ms。wireshark 如何找到这个包呢?

抓包显示,一共请求两次,来源端口分别是34442,34510, 时间是13:57,No 是261。接下来再找到两次response 即可。

No.261 && port == 34442 的请求,最快的resp 如下:

分析了其他的key,得到的结论都类似,redis 返回非常快,根本没什么问题。

3.2 负载分析

odin 是有cpu 监控的,可惜的是,是宿主机的cpu监控。这里cpu 占用看,因为资源隔离,宿主机没问题,但是这个进程的cpu 抖动比较厉害,iostat 显示的情况更真实。这里常用40%,但是定时任务起起来的时候,接近全部打满!抖动是否跟定时任务有关?但问了业务,其实相关性没有那么明显。

3.3 redis sdk 问题排查

sdk 是存在阻塞的可能的,怎么判断sdk 是否阻塞了?两个方式,一种是源码级别追查,第二种是查看实时栈,看是否有lock,wait 之类的逻辑。初步看并没有阻塞逻辑。dump了下线上的栈,看起来,也没有什么问题。但日志确实显示,到底怎么回事?

这里有个认知问题,有runtime 的语言,sdk 都是受runtime 影响的,sdk 写的再好,并不能保证延时,比如你跑下下面这个demo。50个并发,你访问redis 都各种超时。

package main

import (
"flag"
"fmt"
"sync"
"time"

"net/http"
_ "net/http/pprof"

"github.com/gomodule/redigo/redis"
)

var redisAddr string

type Stu struct {
Name string `json:"name"`
Age  int
HIgh bool
sex  string
}

func main() {
flag.StringVar(&redisAddr, "redis", "127.0.0.1:6379", "-redis use redis addr ")
flag.Parse()
go func() {
http.ListenAndServe("0.0.0.0:8003", nil)
}()

wg := sync.WaitGroup{}
wg.Add(1)
for i := 0; i < 20; i++ {
go go_get(wg)
}

wg.Wait()

}

func go_get(wg sync.WaitGroup) {
client, err := redis.Dial("tcp", redisAddr)
if err != nil {
fmt.Println("connect redis error :", err)
return
}
defer client.Close()
for {
time.Sleep(10 * time.Millisecond)
start := time.Now()
client.Do("GET", "test1234")
if cost := time.Now().Sub(start); cost > 10*time.Millisecond {
fmt.Printf("time cost %v \n", cost)
}

}
}
3.4 runtime gc 问题排查及优化

抓了下线上heap 图,查看历史的gc stw 信息:

curl http://localhost:8003/debug/pprof/heap?debug=1 -O heap

上面的数据,是历史stw 时间,没runtime 历史监控只能看这了,数据简直没法看,上面是个256的数组,单位是ns,循环写入。gc 的策略一般主动触发是2min一次,或者内存增长到阈值,先初步认为2min一个点吧。gc 得必须得优化,但是跟日志毛刺的密度比,还对不上。

查看具体的问题在哪,graph 如下:

大头在两个地方,一个是hmget, 一个是json。优化gc 的思路有很多,也不复杂,有实例,参考我个人博客:https://my.oschina.net/u/2950272/blog/1788299。最简单有效的,你先把版本升下吧,起码得升到1.10吧(其实最好1.12。1.8,1.9,1.10, 1.11我都踩过坑),高频服务,1.8一个定时器问题你qps 就上不去了,示例参考:https://my.oschina.net/u/2950272/blog/2247104。

这里是业务同学升版本后的graph:

看下hmget 和json encode 的区别,现在大头全在hmget 上了,效果立杆见影子。这里为啥hmget 这么多?问了下,这是业务逻辑实现,这样做是有问题的。不能影响业务,所有暂时作罢。只升级大版本,stw 好了很多,虽然偶尔也有几十毫秒的毛刺,对比图如下(单位ms):

可惜,问题并没有解决,redis 的抖动没有明显变化:

为什么一直追这redis 查 ,不追着其他接口查,因为redis 要求比较高,是ms 级别,其他的api是百ms级别,毛刺就不明显了。

目前看gc 问题其实还有优化空间,但是成本就高了,得源码优化,改动会比较大,业务方不能接受。而且,当前的gc 大幅改善对接口耗时并没起到立竿见影效果,这里需从其他方面寻找问题。

3.5,抓trace ,查看调用栈
curl http://127.0.0.1:8080/debug/pprof/trace?seconds=300 > trace.out
go tool trace trace.out

线上trace,记录了采样阶段go 都在干嘛,不过因为混合业务代码,你想直接看图,基本是不可能了,打开都得等几分钟(没办法,有业务逻辑)。。。

单独看gc,和heap 之中数据基本一致。这里问题比较严重的是调度,按scheduler wait 排序后数据如下:

加了监控后,看到其实并发的协程数量并不太多,也没出现协程暴增的情况,照理调度并不会这么严重。

影响调度的,还有p 的数量目前是48(宿主机核心数,因为go 启动读了宿主机的核心),线程数是200+。线程数查看ps -T -p pid。8核上跑48个调度线程,会影响调度,这个影响不好评估,但是要优化。我们建议将GOMAXPROC 设置成8,然后重新上线。然后抖动立刻降下来了,效果如下:

对比,当前的调度时间,虽然还是有点难看,但是直接降了快接近一个数量级。

同时,pprof 显示,目前的线程数,降到了以前的1/3。通过perf看线程的上下文切换也少了,同时调度本身也少了。

到此,问题基本查到根因,并解决了。

四,原理分析

为什么获取到错误的cpu 数,会导致业务耗时增长这么严重?主要还是对延迟要求太敏感了,然后又是高频服务,runtime 的影响被放大了。

关于怎么解决获取正确核数的问题,目前golang 服务的解决方式主要是两个,第一,设置环境变量GOMAXPROCS 启动,第二个是显式调用uber/aotomaxprocs。

golang 是如何设置cpu 核数,并取成宿主的核数的呢,追runtime.NumCPU() 发现,其实现是:

细追,发现是 getproccount, 查linux 下源码发现,其实调用的是 sched_getaffinity,直接通过系统调用获取的宿主机核数。

uber/aotomaxprocs 是如何算正确的cpu 核数?其实就是读取 cgroup 接口 /sys/fs/cgroup/cpu/cpu.cfs_quota_us 中的值除以 /sys/fs/cgroup/cpu/cpu.cfs_period_us 中的值并向上取整

这种问题,其实在golang runtime 就解决比较好,像java ,jdk (jdk8u191)以后,都已经能自适应容器和实体服务器了,不太明白为什么会有这种问题,去提个issue。

五, 总结

大部分的服务其实对延时可能没这么敏感,所以没太重视这个问题。为了避免以后再出类似问题,我们在流程上,希望能直接规避掉。我们做的有三点:

第一,给所有go项目加上runtime 监控,如果真出大故障,有时间去临时加pprof 吗?

第二,在所有容器里注入环境变量GOMAXPROCS,并算出cgroup 限制的核数。如果大家有需求自定义p的数量,可以自己显示调用。大家也可以使用uber/aotomaxprocs。

第三,推动大家将线上go 版本升级,特别是高频服务。

内容来自用户分享和网络整理,不保证内容的准确性,如有侵权内容,可联系管理员处理 点击这里给我发消息
标签: