高频 golang 服务接口超时排查&性能调优

原创万鼎铭滴滴技术

桔妹导读：业务中超时抖动是大家平时比较容易遇到的一种技术问题，本文详细记录了一次线上容器中高频 go 服务超时的排查过程。本文可以给大家提供查服务业务超时问题的一些思路，理解为什么 go 服务会获取错 cpu 核数，了解获取宿主 cpu 核数会有多大影响并怎样最小成本避开。

0.

1. 背景

2. 解决思路

3. 现场分析

网络分析

负载分析

redis sdk 问题排查

runtime 问题排查及优化

抓trace ，查看调用栈

4. 原理分析

5. 总结

1.

背景

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

这个项目有非常复杂的业务逻辑，然后要求接口在100 ms 左右能返回。这个服务有密集型 io（调度问题）+定时任务（cpu问题）+常驻内存 cache（gc问题）。频繁访问 redis，在定时逻辑中，业务逻辑一个 request 可能达到上千次 redis Hmget/Get (先不讨论合理性)。复杂业务给问题排查带来比较多干扰因素，这些因素都可能导致抖动。

go version : 1.8，机器是8核+16G 容器，没有开 runtime 监控，redis 的同事初步反馈没有 slowlog。因为rd 也追了很久，到我们这边来的时候，redis 的超时指标监控已经给我们加了，每个key 的查询都会打印日志方便debug。

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

系统cpu问题比较严重，抖动非常大，内存并没有太大问题，但是占用有点大。因为用了local-cache，也可能引起 gc 问题。

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

2.

解决思路

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

第一、首先排查是不是网络问题，查一段时间的 redis slowlog（slowlog 最直接简单）；

第二、本地抓包，看日志中 redis 的 get key 网络耗时跟日志的时间是否对的上；

第三、查机器负载，是否对的上毛刺时间（弹性云机器，宿主机情况比较复杂）；

第四、查 redis sdk，这库我们维护的，看源码，看实时栈，看是否有阻塞（sdk 用了pool，pool 逻辑是否可能造成阻塞）；

第五、查看 runtime 监控，看是否有协程暴增，看 gc stw 时间是否影响 redis（go 版本有点低，同时内存占用大）；

第六、抓 trace ，看调度时间和调度时机是否有问题（并发协程数，GOMAXPROCS cpu负载都会影响调度）；

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

3.

现场分析

▍网络分析

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

1. redis slowlog 经查是正常的，显示没有超过10ms 的 get 请求。

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

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

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

▍负载分析

我们是有 cpu 监控的，可惜的是，是宿主机的 cpu 监控。这里 cpu 占用看，因为资源隔离，宿主机没问题，但是这个进程的 cpu 抖动比较厉害,这里常用40%，但是定时任务起起来的时候，接近全部打满！抖动是否跟定时任务有关？但看监控，其实相关性没有那么明显，redis 超时更频繁。

▍redis sdk 问题排查

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

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

package main


import (
    "flag"
    "fmt"
    "net/http"
    _ "net/http/pprof"
    "sync"
    "time"


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


var redisAddr 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 < 200; 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 {
        start := time.Now()
        client.Do("GET", "test1234")
        if cost := time.Now().Sub(start); cost > 10*time.Millisecond {
            fmt.Printf("time cost %v \n", cost)
        }
    }
}

▍runtime 排查及优化

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

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

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

查看具体的问题在哪，graph 如下：

大头在两个地方，一个是 hmget，一个是 json。优化 gc 的思路有很多，也不复杂，有实例，参考我个人博客。最简单有效的，你先把版本升下吧，高频服务，1.8一个定时器问题你qps 就上不去了，示例参考。

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

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

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

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

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

▍抓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 排序后数据如下：

影响调度的，主要是协程数量和线程数量。

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

线程数查看 ps -T -p pid，线程数是200+，这个数量很奇怪，有点超出预期，8核的容器，默认 p 是8，线程数超过 p 数量20多倍。而从 trace 图上看 p 是48，看着是 go 获取了物理机的核心数。线程数会影响调度，这个影响不好评估，但是要优化。我们建议将 GOMAXPROC 设置成8，然后重新上线。然后抖动立刻降下来了，效果如下：

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

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

4.

原理分析

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

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

golang 是如何设置 cpu 核数，并取成宿主的核数的呢，追 runtime.NumCPU() 发现，其实现细追，发现是 getproccount, 查 linux 下源码发现，其实调用的是 sched_getaffinity，直接通过系统调用获取的宿主机核数。

func getproccount() int32 {
    // This buffer is huge (8 kB) but we are on the system stack
    // and there should be plenty of space (64 kB).
    // Also this is a leaf, so we're not holding up the memory for long.
    // See golang.org/issue/11823.
    // The suggested behavior here is to keep trying with ever-larger
    // buffers, but we don't have a dynamic memory allocator at the
    // moment, so that's a bit tricky and seems like overkill.
    const maxCPUs = 64 * 1024
    var buf [maxCPUs / 8]byte
    r := sched_getaffinity(0, unsafe.Sizeof(buf), &buf[0])
    if r < 0 {
        return 1
    }
    n := int32(0)
    for _, v := range buf[:r] {
        for v != 0 {
            n += int32(v & 1)
            v >>= 1
        }
    }
    if n == 0 {
        n = 1
    }
    return n
}

uber/aotomaxprocs 是如何算正确的cpu 核数？读取 cgroup 接口 /sys/fs/cgroup/cpu/cpu.cfs_quota_us ，然后除以 /sys/fs/cgroup/cpu/cpu.cfs_period_us 并向上取整：

// CPUQuota returns the CPU quota applied with the CPU cgroup controller.
// It is a result of `cpu.cfs_quota_us / cpu.cfs_period_us`. If the value of
// `cpu.cfs_quota_us` was not set (-1), the method returns `(-1, nil)`.
func (cg CGroups) CPUQuota() (float64, bool, error) {
    cpuCGroup, exists := cg[_cgroupSubsysCPU]
    if !exists {
        return -1, false, nil
    }


    cfsQuotaUs, err := cpuCGroup.readInt(_cgroupCPUCFSQuotaUsParam)
    if defined := cfsQuotaUs > 0; err != nil || !defined {
        return -1, defined, err
    }

    cfsPeriodUs, err := cpuCGroup.readInt(_cgroupCPUCFSPeriodUsParam)
if err != nil {
        return -1, false, err
    }

    return float64(cfsQuotaUs) / float64(cfsPeriodUs), true, nil

}

像java ，jdk8u191 以后，都已经能自适应容器和实体服务器了，go 也应该考虑考虑自适应容器核数，毕竟是容器时代。

5.

总结

这个问题排查优化结束了，但怎么让公司其他项目受益？

我们怎么解决其他项目线上线下容器获取错 cpu 数的问题？现在很多项目没开 runtime 监控，线上异常，怎么方便定位问题？这个项目本身还有哪些可以优化的？等等。

第一个问题，我们在镜像里注入环境变量 GOMAXPROCS，并算出 cgroup 限制的核数。如果大家有需求自定义 p 的数量，可以自己显式调用 https://github.com/uber-go/automaxprocs 。镜像注入环境变量，相当于无感帮大家解决了获取错 cpu 的问题。

第二个问题，给我们部门 go 项目加上 runtime 监控，定时上报 runtime 信息同时提供采集pprof 能力。

第三个问题，优化 redis sdk hmget 函数，减少对象分配，业务流程也使用 pipeline 模式，合并 io。

本文作者

▬

万鼎铭

滴滴 | 高级软件开发工程师

目前就职于滴滴出行稳定性与业务中间件组。主要负责业务稳定性、业务系统分析和优化以及go服务基础组件。

推荐阅读
▬


更多推荐
▬

滴滴开源/ Open Source
FastLoad|Levin |AoE |Delta |Mpx | Booster |Chameleon |DDMQ |DroidAssist |Rdebug |Doraemonkit |Kemon|Mand Moblie |virtualApk|获取更多项目

技术干货 / Recommended article
重磅！滴滴跨端框架Chameleon 1.0正式发布 |Android 性能优化之 Activity 启动耗时分析 |HDFS 源码解读：HadoopRPC 实现细节的探究|阅读更多内容

继续滑动看下一个