前幾天告警群里報出一個go服務(wù)grpc接口出現(xiàn)很多超時現(xiàn)象，排查發(fā)現(xiàn)是服務(wù)有內(nèi)存泄露與cpu占用高的問題，在這里將排查的過程記錄一下，給大家提供排查問題的方向與思路，同時借鑒教訓(xùn)，優(yōu)化自己服務(wù)代碼。

發(fā)現(xiàn)超時現(xiàn)象后，登錄機器看了下top，該服務(wù)總共有兩臺機器，發(fā)現(xiàn)02機器的cpu與內(nèi)存占用很高（如下圖第一個進程），而01機器都很低。

正常情況下不會有這么高的資源占用，可能是服務(wù)有資源泄露的問題，資源一致得不到釋放。

首先做的，是重啟服務(wù)，優(yōu)先解決問題，資源泄露的問題可以通過重啟來快速解決，重啟后接口超時現(xiàn)象不再出現(xiàn)，接口耗時恢復(fù)正常。

重啟后，開始排查問題，超時的服務(wù)是B服務(wù)，上游有A服務(wù)調(diào)用B服務(wù)，從A服務(wù)中找了幾個超時的請求，根據(jù)opentracing生成的tracer_id查詢?nèi)罩?，發(fā)現(xiàn)A服務(wù)調(diào)用B服務(wù)超時5s就返回錯誤了，B服務(wù)收到了A服務(wù)的請求，發(fā)現(xiàn)有兩種情況，一種是B立即收到了A的請求，但是處理了400+秒才返回；另一種是A發(fā)出請求400+秒后，B才開始處理請求。

另外發(fā)現(xiàn)grpc請求全部打到一臺機器上，另一臺機器沒什么量。

然后去看了下歷史cpu、內(nèi)存曲線，發(fā)現(xiàn)cpu在15分鐘內(nèi)上升至很高，同時內(nèi)存占用很高的現(xiàn)象。

拉長了內(nèi)存統(tǒng)計時間，發(fā)現(xiàn)A服務(wù)的內(nèi)存在緩慢增長，肯定是有內(nèi)存泄露的問題：

總結(jié)下觀察到的問題：

• 請求為什么全部打到一臺機器上，兩臺機器的前面是有slb的，難道slb沒有發(fā)揮作用嗎？
• cpu占用在15分鐘快速增長的原因是什么？
• 請求處理時間慢的原因是什么？
• 為什么會有內(nèi)存泄露現(xiàn)象出現(xiàn)？

Q1 slb沒有負載均衡

原因

針對Q1，特意去查了下slb的配置，由于slb是根據(jù)權(quán)重輪詢的，可能權(quán)重配置錯誤導(dǎo)致的請求分配不均，但是看了配置，slb的配置并沒有問題，兩臺后端服務(wù)器的權(quán)重相同。

然后去查了下，發(fā)現(xiàn)我們的slb是4層（tcp/udp層）的負載均衡，4層的slb是針對連接做負載均衡的，而不是針對請求，當(dāng)連接的客戶端很少時，負載也可能不均衡，4層的負載均衡是客戶端和服務(wù)器tcp直連。

然后去兩臺機器上netstat看了下，發(fā)現(xiàn)01機器沒有A服務(wù)的連接，02機器有A服務(wù)的連接。同時grpc維持的是長連接并且復(fù)用連接，對于新請求不會新建連接，這樣在第一次經(jīng)過slb的負載均衡創(chuàng)建連接后，grpc的請求會復(fù)用這個連接，請求會全部打到連接的機器上。

如何解決？

知道原因了，那么如何解決呢？可以通過etcd與grpc兩者結(jié)合來實現(xiàn)服務(wù)注冊與服務(wù)發(fā)現(xiàn)，grpc客戶端根據(jù)所有server的ip來實現(xiàn)負載均衡。

Q2 cpu快速增長

原因

對于Q2，由于當(dāng)時服務(wù)沒有設(shè)置pprof，無法看到運行的狀況……后面加了pprof，又不能馬上復(fù)現(xiàn)，所以暫時是通過看代碼的方式來猜測哪些地方可能出了問題- -

想到之前的請求處理了400+秒，并且當(dāng)時內(nèi)存占用很高，代碼中又有worker類的任務(wù)，每秒從數(shù)據(jù)庫中取出數(shù)據(jù)，對每條數(shù)據(jù)啟動一個goroutine處理。

偽代碼如下：

for {
	datas := Mysql.GetDatas()
	for _, v := range datas {
		cur := v
		go func() {
			handle(cur)
		}
	}
	time.Sleep(time.Second)
}

正常情況下，這是沒問題的，但是當(dāng)時機器的內(nèi)存占用接近100%，那么goroutine的處理時間肯定變長，如果處理時間超過1秒甚至遠超一秒，那么這個goroutine還沒處理完，worker又新起了一個goroutine，goroutine的數(shù)量沒有控制，多了以后又占用更多資源，舊的goroutine處理時間更長，worker還是每秒啟動一個新的goroutine……后面就產(chǎn)生了goroutine泄露，這可能是導(dǎo)致cpu增長的主要原因。

所以初步猜測是內(nèi)存泄露問題，導(dǎo)致內(nèi)存占用很高，然后導(dǎo)致goroutine處理時間過長，又導(dǎo)致goroutine泄露，goroutine進一步導(dǎo)致cpu、內(nèi)存增長。

后來在線上加了pprof，但是內(nèi)存泄露比較緩慢，需要等一段時間才能捕獲，到時候在這里補充。

如何解決？

對于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泄露問題導(dǎo)致的cpu占用過高，請求處理不過來了。

如何解決？

參考Q2解決方案

Q4 內(nèi)存泄露問題

原因1

同樣也是直接從代碼的角度排查，借鑒了網(wǎng)上一些人的內(nèi)存泄露經(jīng)驗，發(fā)現(xiàn)一個方法中對于http請求的處理方式可能有問題。

對于每個http請求，該方法每次都會新建一個http.Client與transport, 偽代碼如下。

...
tr := &http.Transport{
   TLSClientConfig: &tls.Config{
      ... // 證書相關(guān)
   },
}
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的注釋我們可以看出這兩個是可以復(fù)用的。

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沒有調(diào)用**Close()**方法，這可能導(dǎo)致潛在的資源泄露。

如何解決？

創(chuàng)建全局的http Client和Transport并且設(shè)置好超時時間等參數(shù)，復(fù)用這個client。http請求返回的response需要調(diào)用http.Response.Body.Close()釋放連接使其可以被其他協(xié)程復(fù)用。

原因2

同時發(fā)現(xiàn)對于mysql查詢結(jié)果的處理，也可能有些問題，偽代碼如下：

rows, err := db.Query(sql, case)
if err != nil {
	return
}
for rows.Next() {
	if err = rows.Scan(...); err != nil{
		return
	}
	...
}

對于sql.Query的結(jié)果rows，如果沒有rows.Close()，但是rows.Scan()讀取了所有的數(shù)據(jù)，那么rows的資源會自動得到釋放；

但是如果Scan發(fā)生錯誤，rows沒有讀取完，又沒有rows.Close()，就可能導(dǎo)致潛在的內(nèi)存泄露。

如何解決？

每次都調(diào)用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正在分析中…… 待補充。

總結(jié)

以上為個人經(jīng)驗，希望能給大家一個參考，也希望大家多多支持腳本之家。

最新評論