golang 高频服务延时抖动追因

一，背景

策略组同窗反馈有个服务上线后 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 负载分析

是有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 版本升级，特别是高频服务。