背景
公司有一个使用golang开发的采集模块,负责调用多个外部系统采集数据;最近做了一次架构上的调整,将采集模块分成api、job两个子模块,并部署到容器中,拆分前部署在虚机上。
现象
部分采集任务在容器中的执行时间比虚机中执行时间要长,8倍左右,本地测试无异常
排查思路
调用外部接口耗时过长?
只有部分任务执行时间长,怀疑容器调用那部分系统接口比较慢,于是在容器中curl外部接口接口,发现并不慢,排除这个可能。
程序问题?
将现有部署在虚机中的正常运行的应用,部署到容器中发现部分任务也会慢; 将部署在容器中的应用部署到虚机后恢复了正常;怀疑是容器本身或容器网络的问题,一时想不到是什么原因,于是开始了漫长的定位
pprof
pprof是golang提供的性能分析工具之一,采集模块已经引入pprof,首先使用它进行排查;
(1). 在容器中安装pprof/flamegraph1
(2). 在容器中执行如下命令,开启pprof的http服务
(3).输入上述http地址
- 查看cpu profiler
没有什么太大异常,只有少许执行逻辑消耗一秒多
- 查看了top/flame graph都没有查看到什么异常
pprof中可以查看以下几类信息
- cpu(CPU Profiling): $HOST/debug/pprof/profile,默认进行 30s 的 CPU Profiling,得到一个分析用的 profile 文件
- block(Block Profiling):$HOST/debug/pprof/block,查看导致阻塞同步的堆栈跟踪
- goroutine:$HOST/debug/pprof/goroutine,查看当前所有运行的 goroutines 堆栈跟踪
- heap(Memory Profiling): $HOST/debug/pprof/heap,查看活动对象的内存分配情况
- mutex(Mutex Profiling):$HOST/debug/pprof/mutex,查看导致互斥锁的竞争持有者的堆栈跟踪
- threadcreate:$HOST/debug/pprof/threadcreate,查看创建新OS线程的堆栈跟踪
由于跟网络有关系,所以想查看下io耗时,pprof无法实现我的需求,想到可以使用trace观察
期间又使用go-torch采集火焰图数据并查看,与pprof类似,感兴趣的同学可自行尝试
trace
trace也是go tool性能问题分析工具之一
(1) 打开trace
主要有以下几块:Goroutine、网络阻塞、同步锁、同步阻塞等
(2) 观察网络IO
一下子看到了60多秒,心里一阵窃喜,但从第一个节点开始已经是50多秒了,仍然不知道是什么原因造成的。又看了gorouting部分
看到network wait那一列耗时占比非常大,心里又是一阵窃喜,基本确定是网络的问题了,点击某一个gorouting进入grouting页面,再根据慢的任务名称找到相应gorouting,点击进入到trace页面
由于network占用大多数时间,连续点了靠后的几个绿条,发现最后一条语句一样,到代码中查看,发现是调用redis的代码,于是在容器中ping redis服务器,又在虚机中ping,发现容器ping的响应时间是虚机的26倍左右;想到公司的服务器分多地部署,于是又查虚机、redis、容器的部署地域,发现虚机和redis在同一地域,而容器和redis服务器不在同一地域,这时才恍然大悟,后面的解决办法就简单了,不在此赘述了;
总结
分析问题要从大到小,逐渐缩小范围,不能一上来就进入细节,这样会耗时较长。开始我怀疑是虚机网络问题,排查了外部系统接口,但遗漏了redis,造成后面花了几个小时仔细排查。其实也是情有可原吧,这个采集模块代码细节我并不熟悉,我的语言技术栈主要是Java,对golang语言不太熟悉,只因负责这个模块开发的同学束手无策,我是这个项目的负责人,只能赶鸭子上架了