每日一博 | 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 负载分析
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 版本升级,特别是高频服务。
低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。
持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。
转载内容版权归作者及来源网站所有,本站原创内容转载请注明来源。
- 上一篇
phpMyAdmin 4.9.2 发布,可视化 MySQL 管理后台
phpMyAdmin 4.9.2 发布了。phpMyAdmin 是一个非常受欢迎的 web MySQL 数据库管理工具。它能够创建和删除数据库,创建/删除/修改表格,删除/编辑/新增字段,执行 SQL 脚本等。 这是一个 bug 修复版本,同时带来了一些安全修复,主要包括: 修复了与 cookie 名称有关的“无法设置会话 cookie”错误。 修复使用 MySQL 8.0.3 及更高版本的问题 修复 PHP 弃用错误 修复了删除查询后导出用户可能会删除用户的情况 修复错误的无操作特权警告 修复了复制数据库的特权以及使用 MariaDB 移动列的其它一些问题 修复了 phpMyAdmin 在导出期间使用 Shift 键选择时未选择所有值的问题 更新说明: https://www.phpmyadmin.net/news/2019/11/22/phpmyadmin-492-released
- 下一篇
英特尔推出采用数据并行 C ++ 编程语言的 OneAPI
英特尔在 Supercomputing 2019 活动中推出了OneAPI 编程模型。 据悉,OneAPI 计划是英特尔的统一编程方法,可简化跨不同计算体系结构的应用程序开发。它将有助于使用现代C ++功能对CPU和加速器进行编程,这些功能通过称为Data Parallel C ++(DPC ++)的新编程语言来表达并行性。 而关于数据并行C ++(即DPC ++)编程语言的概述是:DPC ++ 是一种编程语言,其允许开发人员使用一个源代码文档为CPU,GPU,FPGA和其他硬件加速器进行编码。它是一种开放的,跨行业的编程语言(基于C ++概念和SYCL),被吹捧为“单一体系结构专有语言的替代”。 此处的目标是简化编程并允许跨硬件目标重复使用代码,同时允许调整到特定的加速器。 英特尔OneAPI Beta版支持两种编程样式:直接编程和API编程。其中,DPC ++则属于直接编程领域。 值得一提的是,这两种编程样式将提供有效的统一开发模型,从而促进跨各种异构处理硬件的完整本机代码性能。 参考消息:https://fossbytes.com/intel-launches-oneapi-wi...
相关文章
文章评论
共有0条评论来说两句吧...
文章二维码
点击排行
推荐阅读
最新文章
- CentOS8编译安装MySQL8.0.19
- CentOS关闭SELinux安全模块
- Linux系统CentOS6、CentOS7手动修改IP地址
- Docker安装Oracle12C,快速搭建Oracle学习环境
- CentOS8,CentOS7,CentOS6编译安装Redis5.0.7
- CentOS7,8上快速安装Gitea,搭建Git服务器
- Windows10,CentOS7,CentOS8安装MongoDB4.0.16
- SpringBoot2编写第一个Controller,响应你的http请求并返回结果
- 设置Eclipse缩进为4个空格,增强代码规范
- Windows10,CentOS7,CentOS8安装Nodejs环境