记一次Go websocket项目内存泄露排查 + 使用Go pprof定位内存泄露

2017/05/27 Golang

从同事接手了一个项目。这个项目是用了<go-socket.io>这个库,仿照socket.io的功能,和前端进行交互。因为之前是用socket.io做的后端,但是 觉得性能不够用了,就改用Go来进行重构。重构之后,发生内存泄露的现象。这个项目峰值大概维护1w-1.5w个socket长连接,一开始内存消耗量大概到2g-3g。 然而,当连接数没有增长的情况下,随着运行时间的增长,内存也在增长。并且大概一个多小时的时间,内存就涨到了10g,而且连接数才1w多,说好的支撑”百万连接呢”。如果不进行重启服务操作,内存会涨到14g(16g的内存)。所以,确定是有内存泄露。我需要做的就是找到内存泄露的原因,修复这个问题。

Go提供了一个已经足够强大的pprof库。这样,我直接使用这个库,来查看内存的消耗情况。

在main.go 中加入 <import _ "net/http/pprof">,因为项目中有http请求,所以,当有http请求的时候,pprof会帮我们分析资源的使用情况。我只针对我的操作,描述如何使用<pprof>,具体的操作,可以搜相关文档或文章。

然后,build。把build后的二进制文件传到服务器,重新启动项目。在本地可以用websocketbench 这样的测试工具。因为在本地,内存逐渐增长的环境没能被复现出来,所以,决定用线上环境来进行排查。

让程序跑1个小时,这时内存涨到了3.9g。socket 连接数为6500+。在浏览器输入: <host_name:9090/debug/pprof>,显示pprof 的主页。 网页会显示几个选项,有 heap、goroutine等。这时候的<goroutine>数量是24497。我点击heap,进入到 <host_name:9090/debug/pprof/heap?debug=1> 移到最下面:

# runtime.MemStats
# Alloc = 3537545936
# TotalAlloc = 217546115776
# Sys = 4223095608
# Lookups = 1321203
# Mallocs = 1558757559
# Frees = 1533787828
# HeapAlloc = 3537545936            进程堆内存分配使用的空间,通常是用户new出来的堆对象,包含未被gc掉的。
# HeapSys = 3784015872             进程从系统获得的堆内存,因为golang底层使用TCmalloc机制,会缓存一部分堆内存,虚拟地址空间
# HeapIdle = 167993344             堆中空闲但没有释放还给系统的内存使用量
# HeapInuse = 3616022528            堆中正在使用的内存使用量
# HeapReleased = 0
# HeapObjects = 24969731
# Stack = 221347840 / 221347840
# MSpan = 50597304 / 51511296
# MCache = 9600 / 16384
# BuckHashSys = 3240312
# GCSys = 148043776
# OtherSys = 14920128
# NextGC = 3824913056             下一次内存使用量达到多少值时触发GC

Then,在我本地build项目的目录,执行:

go tool pprof ./bin/my-go-app-20170426103223 http://xxx.xxx.xxx.xxx:9090/debug/pprof/heap

我们可以看数据top来查看正在使用的对象较多的函数入口。通常用来检测有没有不符合预期的内存 对象引用。

(pprof) top
1517.34MB of 1870.97MB total (81.10%)
Dropped 760 nodes (cum <= 9.35MB)
Showing top 10 nodes out of 83 (cum >= 43.01MB)
      flat  flat%   sum%        cum   cum%
  332.58MB 17.78% 17.78%   332.58MB 17.78%  runtime.rawstringtmp
  312.09MB 16.68% 34.46%   339.85MB 18.16%  runtime.mapassign
  274.15MB 14.65% 49.11%   274.15MB 14.65%  runtime.makemap
  165.06MB  8.82% 57.93%   165.06MB  8.82%  gopkg.in/mgo%2ev2.copySession
  121.17MB  6.48% 64.41%   121.17MB  6.48%  github.com/gorilla/websocket.newConn
   96.51MB  5.16% 69.57%    97.51MB  5.21%  context.WithCancel
   82.52MB  4.41% 73.98%   703.77MB 37.62%  net/http.readRequest
   45.51MB  2.43% 76.41%   454.68MB 24.30%  net/textproto.(*Reader).ReadMIMEHeader
   44.74MB  2.39% 78.80%    55.25MB  2.95%  _/home/user/Documents/udesk_vistor_go/app/controllers.SocketConnection
   43.01MB  2.30% 81.10%    43.01MB  2.30%  net/url.parse

上面列出了现在系统哪些包和库的函数的内存使用量,可以使用 list lib_name 来定位到具体代码的位置。 当我们不明确这些调用时是被哪些函数引起的时,我们可以输入top -cum来查找,-cum的意思就是,将函数调用关系 中的数据进行累积,比如A函数调用的B函数,则B函数中的内存分配量也会累积到A上面,这样就可以很容易的找出调用链。

1517.34MB of 1870.97MB total (81.10%)

这一行统计了heap内存的使用量。和浏览器中统计的会有误差。

  • flat 表示函数自身执行所用内存

  • cum 表示执行函数自身和其调用的函数所用的内存和

我们观察占用内存量最多的前三项目:

332.58MB 17.78% 17.78%   332.58MB 17.78%  runtime.rawstringtmp
312.09MB 16.68% 34.46%   339.85MB 18.16%  runtime.mapassign
274.15MB 14.65% 49.11%   274.15MB 14.65%  runtime.makemap

这是Go的原生库的操作,是对字符串和新建map的操作。之前系统用来一个全局map的库<github.com/streamrail/concurrent-map>,作为全局map,存储相关数据。 起初怀疑是它的问题,经过修改,去掉了这个全局map,而是使用mongoDB来存储数据。之后观察发现,内存的上涨速度变慢了,但是,内存随着时间仍然上涨, 内存泄露问题仍然存在。

在看过整个项目的代码后,排除代码使用的问题。该close()的地方,比如连接或是MongoDB的操作,都应该没问题。

然后,把关注的移到了使用的第三方库上。在线上进行pprof的时候,观察发现goroutine的数量,当连接数量减少时,一段时间,goroutine的数量也会减少。 Google <go-socket.io> 这个库,也并没搜到其内存泄露的问题。看了<go-socket.io>的源码,它的实现机制其实和真正的<socket.io>不是一样的。<socket.io><nodejs>的一个库,原理基于<nodejs>的事件驱动模式。而<go-scoket.io>这个库,当有连接来的时候会起多个goroutine,在goroutine中进行处理,类似多线程的方式,基于Go对goroutine的调度进行处理。

在本地对 <github.com/pschlump/jsonp> <gopkg.in/mgo.v2/bson> 进行单独测试,没有内存泄露的情况发生。 对使用到 <github.com/kidstuff/mongostore> 和 <github.com/gorilla/sessions> 的接口进行测试,本地也没有内存上涨的情况发生。(以上测试发生在两周前,并且用了一周的时间进行了逐步排查)

大概两个半小时后的数据:

28600 groutines 4800 connections 8.6g Memory  MongoDB connection 464
# runtime.MemStats
# Alloc = 4523698072
# TotalAlloc = 402074198032
# Sys = 9180321800
# Lookups = 2255805
# Mallocs = 2692470963
# Frees = 2656425569
# HeapAlloc = 4523698072
# HeapSys = 7991754752
# HeapIdle = 2413297664
# HeapInuse = 5578457088
# HeapReleased = 0
# HeapObjects = 36045394
# Stack = 729907200 / 729907200
# MSpan = 100263152 / 108544000
# MCache = 9600 / 16384
# BuckHashSys = 3443088
# GCSys = 320460800
# OtherSys = 26195576
# NextGC = 7747394592
(pprof) top
3016.30MB of 3658.47MB total (82.45%)
Dropped 774 nodes (cum <= 18.29MB)
Showing top 10 nodes out of 86 (cum >= 313.05MB)
      flat  flat%   sum%        cum   cum%
  655.15MB 17.91% 17.91%   655.15MB 17.91%  runtime.rawstringtmp
  643.69MB 17.59% 35.50%   693.39MB 18.95%  runtime.mapassign
  561.81MB 15.36% 50.86%   561.81MB 15.36%  runtime.makemap
  324.61MB  8.87% 59.73%   324.61MB  8.87%  gopkg.in/mgo%2ev2.copySession
  200.96MB  5.49% 65.22%   200.96MB  5.49%  github.com/gorilla/websocket.newConn
  195.02MB  5.33% 70.55%   195.52MB  5.34%  context.WithCancel
  167.04MB  4.57% 75.12%  1397.52MB 38.20%  net/http.readRequest
   92.51MB  2.53% 77.65%   918.37MB 25.10%  net/textproto.(*Reader).ReadMIMEHeader
   89.01MB  2.43% 80.08%    89.01MB  2.43%  github.com/gorilla/securecookie.New
   86.51MB  2.36% 82.45%   313.05MB  8.56%  github.com/kidstuff/mongostore.(*MongoStore).New

可以看到,heap的内存使用量确实上涨了,但是,实际的socket连接数是减少的。

第二天,将数据和同事讨论。关注到了这两行:

167.04MB  4.57% 75.12%  1397.52MB 38.20%  net/http.readRequest
 92.51MB  2.53% 77.65%   918.37MB 25.10%  net/textproto.(*Reader).ReadMIMEHeader

他们的cum很高。这是之前的观察测试中没有注意到的。cum表示了执行函数自身和其调用的函数所用的内存和。说明这两个地方的整个调用函数中占用了很多内存。(还原真实的环境,数据才最有效) 然后Google net/http.readRequest memory leak 和 net/textproto.(*Reader).ReadMIMEHeader memory leak。其中有一个人也遇到相似的内存泄露的问题,也是使用了go-socket.io这个库。他解决了这个内存泄露问题,不是因为go-socket.io的原因,而是因为他使用的一个库用到了context,但是context的值没有清除。直觉告诉我们,很有可能我们也是在使用类似context的时候,数据没有清空。

然后我全局搜了 context。发现项目中使用了 <github.com/gorilla/context>这个库。并不是我们直接使用,而是在使用<github.com/gorilla/sessions>的时候,使用了<github.com/gorilla/context>

有可能是<github.com/gorilla/sessions>的问题。来到<github.com/gorilla/sessions>的主页查看文档,在网页搜索”leak”发现了下面这句:

Important Note: If you aren’t using gorilla/mux, you need to wrap your handlers with context.ClearHandler as or else you will leak memory! An easy way to do this is to wrap the top-level mux when calling http.ListenAndServe: http.ListenAndServe(“:8080”, context.ClearHandler(http.DefaultServeMux))

意思是,如果不用我们自家的 <gorilla/mux> <gorilla/sessions> 包会有内存泄露。或者是 

http.ListenAndServe(“:8080”, context.ClearHandler(http.DefaultServeMux))

这样操作。

What the hell……我震惊了!

我继续搜索到这个方法 <context.ClearHandler> 相关的代码如下:

var (
	mutex sync.RWMutex
	data  = make(map[*http.Request]map[interface{}]interface{})
	datat = make(map[*http.Request]int64)
)

func ClearHandler(h http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		defer Clear(r)
		h.ServeHTTP(w, r)
	})
}

// Clear removes all values stored for a given request.
//
// This is usually called by a handler wrapper to clean up request
// variables at the end of a request lifetime. See ClearHandler().
func Clear(r *http.Request) {
	mutex.Lock()
	clear(r)
	mutex.Unlock()
}

// clear is Clear without the lock.
func clear(r *http.Request) {
	delete(data, r)
	delete(datat, r)
}

顿时明白了。<gorilla/sessions> 这个库使用了 <gorilla/context>

<gorilla/context>这个库定义了两个全局变量的map。 当每个request来的时候,就将往这两个全局map中以http.Request对象为key存值。如果没有调用<context.ClearHandler>方法。即使这个request是已经关闭了,但是,由于这个request作为了全局变量map的key,使得Go GC没法回收已经结束的request对象。内存就很快就被消耗完了。(比较奇怪的是,没在本地复现)

问题找到了,马上修复。上线代码,观察了3个多小时。

The world has returned calm.

1w+ 的socket 连接没有超过2g内存使用量。这才是Go应有的表现(百万连接不是梦)

总结:

  • Go pprof is awesome

  • Global variable is devil

  • go-socket.io is more powerful than socket.io

参考链接:

那位遇到同样问题的人的提问

gorilla/sessions

pprof的使用

一篇文章

Search

    Table of Contents