文档章节

golang 高频服务延时抖动追因

caucy
 caucy
发布于 11/20 19:09
字数 2627
阅读 2466
收藏 64

【推荐】2019 Java 开发者跳槽指南.pdf(吐血整理) >>>

一,背景

策略组同学反馈有个服务上线后 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的数量,可以自己显示调用。大家也可以使用https://github.com/uber-go/automaxprocs。

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

© 著作权归作者所有

caucy
粉丝 60
博文 73
码字总数 51186
作品 0
东城
程序员
私信 提问
加载中

评论(7)

linshi2019
linshi2019
看迷糊了,什么原因怎么解决的
mickelfeng
mickelfeng
不错
mickelfeng
mickelfeng
用的什么监控软件
caucy
caucy 博主
公司监控,比较简单,跟zabbix 差不多
zcx2001
zcx2001
能提供一下uber/aotomaxprocs这个库的地址吗? 我没找到啊
李昊
李昊
very nice!
每日一博 | Golang 高频服务延时抖动追因

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

oschina
11/23
82
1
SylixOS周期定时抖动分析

1.概述 自动化与控制行业中有很多场景需要循环周期控制,而运动控制领域对循环周期控制的时间确定性要求尤为严格,周期抖动的时间确定性和周期控制的极限范围直接影响运动控制产品的质量和性...

Jackstraw瑞
2017/09/18
0
0
利用ffmpeg打造播放器直播观看公网rtmp1s延时极致优化

此文章主旨为了说明在无须修改ffmpeg任何源码,以及修改编码参数设置以及服务器、CDN配置,优化播放器即可达到1s延时效果。 关于rtmp直播流打开慢和延时大的问题, 很多人共识播放器在公网都...

地瓜儿
2016/08/19
5K
3
webRTC中音频相关的netEQ(一)

上篇文章(语音通信中终端上的时延(latency)及减小方法)说从本篇开始会切入webRTC中的netEQ主题,netEQ是webRTC中音频技术方面的两大核心技术之一(另一核心技术是音频的前后处理,包括AEC...

2018/07/16
0
0
网络性能测试工具Iperf介绍

【概要】Iperf是一款网络性能测试工具,可以方便的用它进行SDN网络带宽和网络质量的测试,Iperf支持协议、定时、缓冲区等参数的配置调整,报告TCP/UDP最大带宽、延迟抖动、数据包丢失等统计信...

SDN_LAB
2014/12/04
432
1

没有更多内容

加载失败,请刷新页面

加载更多

交换机switch 的shutdown 与 no shutdown

shutdown是关闭接口(端口),接口状态会变为DOWN,no shutdown是激活接口(端口),状态变为UP,一般在给vlan或者端口配置管理ip或者端口ip后使用。 有时候我们配置某个端口前会需要把端口关闭到...

刘日辉
55分钟前
5
0
AOP底层源码分析

思维导图 AOP AOP: 面向切面编程[底层就是动态代理] 指程序在运行期间动态的将某段代码切入到指定方法位置进行运行的编程方式。 AOP通知方式 前置通知: logStart(),在目标方法(div)运行之前运...

volc1612
今天
5
0
OSChina 周六乱弹 —— 别听他们的,你不胖你只是毛茸茸的

Osc乱弹歌单(2019)请戳(这里) 【今日歌曲】 @且无需多言 :分享Rise Against的单曲《Audience Of One (Ghost Note Symphonies)》: 硬核朋克不插电版本,隐藏在喧嚣下的柔情! 《Audienc...

小小编辑
今天
76
3
apache httpClient实现代理发送Post请求

CredentialsProvider credsProvider = new BasicCredentialsProvider(); credsProvider.setCredentials( new AuthScope("host", port), new UsernamePasswordCredentials(username, password......

huangkejie
今天
6
0
SpringCloud

单体应用存在的问题 ● 随着业务的发展,开发变得越来越复杂。 ● 修改、新增某个功能,需要对整个系统进行测试,重新部署。 ● 一个模块出现问题,很可能导致整个系统崩溃。 ● 多个开发团队...

Star永恒
今天
5
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部