記一次Go websocket　專案記憶體洩露排查 + 使用Go pprof定位記憶體洩露

從同事接手了一個專案。這個專案是用了<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　這樣的測試工具。因為在本地，記憶體逐漸增長的環境沒能被複現出來，所以，決定用線上環境來進行排查。

讓程式跑１個小時，這時記憶體漲到了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　　　　　　　　　　　　分配給堆的記憶體使用量
# HeapSys = 3784015872　　　　　　　　　　　　　堆佔用系統的記憶體使用量
# 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

(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　來定位到具體程式碼的位置。

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很高。這是之前的觀察測試中沒有注意到的。(還原真實的環境，資料才最有效) 然後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物件。記憶體就很快就被消耗完了。(比較奇怪的是，沒在本地復現)

問題找到了，馬上修復。上線程式碼，觀察了３個多小時。

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的使用