一，背景

策略组同学反馈有个服务上线后 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 版本升级，特别是高频服务。