線上golang grpc服務資源泄露問題排查
前幾天告警群里報出一個go服務grpc接口出現(xiàn)很多超時現(xiàn)象,排查發(fā)現(xiàn)是服務有內存泄露與cpu占用高的問題,在這里將排查的過程記錄一下,給大家提供排查問題的方向與思路,同時借鑒教訓,優(yōu)化自己服務代碼。
發(fā)現(xiàn)超時現(xiàn)象后,登錄機器看了下top,該服務總共有兩臺機器,發(fā)現(xiàn)02機器的cpu與內存占用很高(如下圖第一個進程),而01機器都很低。
正常情況下不會有這么高的資源占用,可能是服務有資源泄露的問題,資源一致得不到釋放。
首先做的,是重啟服務,優(yōu)先解決問題,資源泄露的問題可以通過重啟來快速解決,重啟后接口超時現(xiàn)象不再出現(xiàn),接口耗時恢復正常。
重啟后,開始排查問題,超時的服務是B服務,上游有A服務調用B服務,從A服務中找了幾個超時的請求,根據opentracing生成的tracer_id查詢日志,發(fā)現(xiàn)A服務調用B服務超時5s就返回錯誤了,B服務收到了A服務的請求,發(fā)現(xiàn)有兩種情況,一種是B立即收到了A的請求,但是處理了400+秒才返回;另一種是A發(fā)出請求400+秒后,B才開始處理請求。
另外發(fā)現(xiàn)grpc請求全部打到一臺機器上,另一臺機器沒什么量。
然后去看了下歷史cpu、內存曲線,發(fā)現(xiàn)cpu在15分鐘內上升至很高,同時內存占用很高的現(xiàn)象。
拉長了內存統(tǒng)計時間,發(fā)現(xiàn)A服務的內存在緩慢增長,肯定是有內存泄露的問題:
總結下觀察到的問題:
- 請求為什么全部打到一臺機器上,兩臺機器的前面是有slb的,難道slb沒有發(fā)揮作用嗎?
- cpu占用在15分鐘快速增長的原因是什么?
- 請求處理時間慢的原因是什么?
- 為什么會有內存泄露現(xiàn)象出現(xiàn)?
Q1 slb沒有負載均衡
原因
針對Q1,特意去查了下slb的配置,由于slb是根據權重輪詢的,可能權重配置錯誤導致的請求分配不均,但是看了配置,slb的配置并沒有問題,兩臺后端服務器的權重相同。
然后去查了下,發(fā)現(xiàn)我們的slb是4層(tcp/udp層)的負載均衡,4層的slb是針對連接做負載均衡的,而不是針對請求,當連接的客戶端很少時,負載也可能不均衡,4層的負載均衡是客戶端和服務器tcp直連。
然后去兩臺機器上netstat看了下,發(fā)現(xiàn)01機器沒有A服務的連接,02機器有A服務的連接。同時grpc維持的是長連接并且復用連接,對于新請求不會新建連接,這樣在第一次經過slb的負載均衡創(chuàng)建連接后,grpc的請求會復用這個連接,請求會全部打到連接的機器上。
如何解決?
知道原因了,那么如何解決呢?可以通過etcd與grpc兩者結合來實現(xiàn)服務注冊與服務發(fā)現(xiàn),grpc客戶端根據所有server的ip來實現(xiàn)負載均衡。
Q2 cpu快速增長
原因
對于Q2,由于當時服務沒有設置pprof,無法看到運行的狀況……后面加了pprof,又不能馬上復現(xiàn),所以暫時是通過看代碼的方式來猜測哪些地方可能出了問題- -
想到之前的請求處理了400+秒,并且當時內存占用很高,代碼中又有worker類的任務,每秒從數(shù)據庫中取出數(shù)據,對每條數(shù)據啟動一個goroutine處理。
偽代碼如下:
for { datas := Mysql.GetDatas() for _, v := range datas { cur := v go func() { handle(cur) } } time.Sleep(time.Second) }
正常情況下,這是沒問題的,但是當時機器的內存占用接近100%,那么goroutine的處理時間肯定變長,如果處理時間超過1秒甚至遠超一秒,那么這個goroutine還沒處理完,worker又新起了一個goroutine,goroutine的數(shù)量沒有控制,多了以后又占用更多資源,舊的goroutine處理時間更長,worker還是每秒啟動一個新的goroutine……后面就產生了goroutine泄露,這可能是導致cpu增長的主要原因。
所以初步猜測是內存泄露問題,導致內存占用很高,然后導致goroutine處理時間過長,又導致goroutine泄露,goroutine進一步導致cpu、內存增長。
后來在線上加了pprof,但是內存泄露比較緩慢,需要等一段時間才能捕獲,到時候在這里補充。
如何解決?
對于goroutine泄露的解決,自然是控制goroutine的數(shù)量,我把偽代碼改成了如下來控制goroutine(判斷超過限制數(shù)量就sleep):
int32 runningG = 0 const maxRunningG = 200 for { if atomic.LoadInt32(&runningG) > maxRunningG { time.Sleep(time.Seconds * 3) continue } datas := Mysql.GetDatas() for _, v := range datas { cur := v atomic.AddInt32(&runningG, 1) go func() { handle(cur) atomic.AddInt32(&runningG, -1) } } time.Sleep(time.Second) }
Q3 請求處理緩慢
原因
處理請求緩慢的原因可能是Q2 goroutine泄露問題導致的cpu占用過高,請求處理不過來了。
如何解決?
參考Q2解決方案
Q4 內存泄露問題
原因1
同樣也是直接從代碼的角度排查,借鑒了網上一些人的內存泄露經驗,發(fā)現(xiàn)一個方法中對于http請求的處理方式可能有問題。
對于每個http請求,該方法每次都會新建一個http.Client與transport, 偽代碼如下。
... tr := &http.Transport{ TLSClientConfig: &tls.Config{ ... // 證書相關 }, } client := &http.Client{Transport: tr} response, err := client.Post(url, contentType, body) if err != nil { return } responseByte, err := ioutil.ReadAll(response.Body) if err != nil { return } ...
而通過http.Client與transport的注釋我們可以看出這兩個是可以復用的。
http.Client:
// The Client's Transport typically has internal state (cached TCP // connections), so Clients should be reused instead of created as // needed. Clients are safe for concurrent use by multiple goroutines. //
http.Transport:
// Transports should be reused instead of created as needed. // Transports are safe for concurrent use by multiple goroutines.
且該方法對于http.Response.Body沒有調用**Close()**方法,這可能導致潛在的資源泄露。
如何解決?
創(chuàng)建全局的http Client和Transport并且設置好超時時間等參數(shù),復用這個client。http請求返回的response需要調用http.Response.Body.Close()釋放連接使其可以被其他協(xié)程復用。
原因2
同時發(fā)現(xiàn)對于mysql查詢結果的處理,也可能有些問題,偽代碼如下:
rows, err := db.Query(sql, case) if err != nil { return } for rows.Next() { if err = rows.Scan(...); err != nil{ return } ... }
對于sql.Query的結果rows,如果沒有rows.Close(),但是rows.Scan()讀取了所有的數(shù)據,那么rows的資源會自動得到釋放;
但是如果Scan發(fā)生錯誤,rows沒有讀取完,又沒有rows.Close(),就可能導致潛在的內存泄露。
如何解決?
每次都調用rows.Close()方法來釋放資源。
rows, err := db.Query(sql, case) if err != nil { return } defer rows.Close() // for rows.Next() { if err = rows.Scan(...); err != nil{ return } ... }
其他原因
通過pprof正在分析中…… 待補充。
總結
以上為個人經驗,希望能給大家一個參考,也希望大家多多支持腳本之家。