golang创建大量线程的问题分析
背景是我们在公司造了一个Go web框架,性能也非常优异。
但是在迁入k8s之后(k8s也是我们正在推动的新项目),我们在做压测过程中却发现程序动不动就cpu打满,远远不如之前的性能。
曲折的前路
一开始没有线上k8s集群的权限,而且对框架比较自信,所以一直怀疑是不是k8s有什么大坑,就没往go程序自身去怀疑。
直到我申请到了k8s线上集群权限,目睹了压测的过程,发现个别POD中的Golang竟然创建了高达6000个线程,分配过的内存高达80G之多。
于是我开始怀疑Golang是不是有什么傻X的设计,为什么会无限的创建线程,说好的协程呢?
于是我找到了一些关于golang线程控制的文章:https://stackoverflow.com/questions/39245660/number-of-threads-used-by-go-runtime
原来GOMAXPROCS设置的线程数量只是一个默认值,当我们代码调用syscall并且block线程较长时间的话,runtime会继续新建线程来尽快调度其他协程,这个上限是10000个线程。
我对框架是非常自信的,框架里几乎不可能有任何类似于磁盘IO或者锁之类的操作,而且之前在其他业务的压测下表现非常优异,唯一区别就是现在运行在K8S里。
为了找出问题所在,我在VM搭建了该Go程序,自己压测观察了一下程序的表现,竟然CPU的sys比usr还高,这让我匪夷所思,难道框架有什么变化?
我立即用perf top命令查看了一下到底是什么syscall导致的:
我得天,哪来的lock?
使用pprof采样
以前压测框架我也看过机器各项指标,完全不存在这个情况。
为了找出原因,我需要给go程序打开pprof采集,以便清楚的找到问题所在。
我采用了golang的http pprof功能,它的作用是我们可以通过调用HTTP接口触发程序进行一段时间的采样,然后HTTP接口会返回本次采样的一个文件,我们拿到文件就可以在自己的电脑上利用go命令行工具查看采集结果了。
因为框架采用的是Gin作为路由层,已经有社区提供了封装好的简便方法来注册pprof的HTTP接口到路由中:github.com/gin-contrib/pprof 。
这个库做的事情很简单:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
func Register(r *gin.Engine, prefixOptions ...string) { prefix := getPrefix(prefixOptions...) prefixRouter := r.Group(prefix) { prefixRouter.GET("/", pprofHandler(pprof.Index)) prefixRouter.GET("/cmdline", pprofHandler(pprof.Cmdline)) prefixRouter.GET("/profile", pprofHandler(pprof.Profile)) prefixRouter.POST("/symbol", pprofHandler(pprof.Symbol)) prefixRouter.GET("/symbol", pprofHandler(pprof.Symbol)) prefixRouter.GET("/trace", pprofHandler(pprof.Trace)) prefixRouter.GET("/allocs", pprofHandler(pprof.Handler("allocs").ServeHTTP)) prefixRouter.GET("/block", pprofHandler(pprof.Handler("block").ServeHTTP)) prefixRouter.GET("/goroutine", pprofHandler(pprof.Handler("goroutine").ServeHTTP)) prefixRouter.GET("/heap", pprofHandler(pprof.Handler("heap").ServeHTTP)) prefixRouter.GET("/mutex", pprofHandler(pprof.Handler("mutex").ServeHTTP)) prefixRouter.GET("/threadcreate", pprofHandler(pprof.Handler("threadcreate").ServeHTTP)) } } |
标准库pprof提供了一些列采集项的http handlFunc,只需要适配到Gin路由函数的样子,注册到路由上即可。
现在开始持续压测程序,然后通过HTTP调用你需要的指标对应的URL,那么就可以下载回来对应的采集数据。
我比较在乎profile,它是关于CPU的一个采样数据,所以我们这样来下载它:
1 2 3 |
[root@localhost ~]# go tool pprof http://localhost:8109/debug/pprof/profile?seconds=3 Fetching profile over HTTP from http://localhost:8109/debug/pprof/profile?seconds=3 Saved profile in /root/pprof/pprof.web-user-dc.samples.cpu.003.pb.gz |
注意,URL后面要带一个seconds参数表示采样的持续时间,这个时间不要超过HTTP框架的超时时间,否则采样到一半HTTP接口都超时了。
等待3秒后,采样数据就会下载到本地,提示你保存在什么路径下。
现在可以把服务器上的该采样文件拷贝回自己的开发机,然后利用命令行工具打开它:
1 |
go tool pprof -http=":8081" ~/Downloads/pprof.web-user-dc.samples.cpu.003.pb.gz |
这样的话,go会打开一个服务端监听在8081端口,我们用浏览器访问可以看到可视化的分析结果页面。
分析pprof结果
调用关系图中,飘红的调用路径是问题所在。
我发现在我们的cat调用链追踪的middleware中竟然调用了一个我看着很陌生的函数,这个函数占据了程序大部分的运行时间。
如果我们看一下火焰图,会看到更清晰的时间分布(图片右键单独窗口打开):
可见GetLocalHostIP方法内部调用大量syscall,也就难怪golang runtime因为syscall block而创建大量线程了。
与同事沟通,发现是它在最近的某个框架版本引入了这段代码,每次请求都在重复的获取本机的网卡列表信息,而这个操作是非常重的。因为这段代码引入的时间正好在K8S压测之前,所以导致一度误判以为K8S造成了该异常现象。
为了进一步定位这个问题,我们还有一个很实用的方法,就是获取各个协程的执行栈,如果观察到大量的协程都在执行同一段代码,那很有可能这段代码就是有性能问题的慢执行代码,所以我们调用采样goroutine的HTTP接口下载文件:
1 |
go tool pprof http://localhost:8109/debug/pprof/goroutine |
这里不需要加seconds参数,因为它抓的是瞬时各个goroutine正在执行的调用栈。
只需要在上述命令打开的交互模式下,输入traces就可以看到所有goroutine的调用栈,然后我发现大量类似于这样的代码:
那么该问题就此也就基本定位了,修复好压测再也没有出现疯狂创建线程的问题。
希望这个过程对大家定位自己的问题有所帮助,如果遇到golang创建大量线程的情况,首先应该pprof分析是否有syscall block,这是它唯一创建线程的理由。
如果文章帮助您解决了工作难题,您可以帮我点击屏幕上的任意广告,或者赞助少量费用来支持我的持续创作,谢谢~

厉害
我发现每调用一次http请求数据,都会创建一个线程,这玩意能用吗
谁告诉你的。。
1
1