golang 高頻服務延時抖動追因

一，背景

策略組同窗反饋有個服務上線後 redis 寫超時很是嚴重，嚴重到什麼地步呢，寫redis 毛刺超過100ms！ 並且不是隨機出現，很是多，並且均勻，致使整個接口超時嚴重。由於用的redis 庫是由咱們組維護，因此任務落咱們組小夥伴頭上了。

這個項目有很是複雜的業務邏輯，有密集型io（調度問題）+定時任務（cpu問題）+常駐內存cache（gc問題），頻繁訪問redis，在定時邏輯中，業務邏輯須要一個request 可能達到上千次redis Hmget+get(先不討論合理性)。 背景比較複雜， 是個golang 服務，接口延遲要求百ms級。

go version : 1.8，機器是8核+16G 容器，沒有開runtime 監控，redis 的同事初步反饋沒有slowlog。由於rd 也追了好久，到咱們這邊來的時候，redis 的超時指標監控已經給咱們加了。

redis get 接口的耗時監控顯示以下，由於高頻請求，大部分耗時是小於10ms 的，可是這毛刺看着很是嚴重，是不可忍受了。

系統cpu問題比較嚴重，抖動很是大，內存並無太大問題，可是佔用有點大，比較有意思的事，由於用了local-cache，其實，咱們剛開始覺得是local-cache 致使的gc引發的。

由於沒有加runtime 監控，其餘信息暫不可知。

二，解決思路

由於追查接口毛刺比較複雜，咱們的原則是不影響業務的狀況下，儘可能少上線的將業務問題解決。

咱們初步給了個追查思路：

第一，首先排查是否是網絡問題，對redis slowlog（redis 自己自帶監控）；

第二， 本地抓包，看日誌中redis 的get 時間跟真實網絡的時間是否對的上（抓包最可靠）；

第三，對機器負載，是否對的上毛刺時間（cpu 資源不夠，調度不過來毛刺也正常）；

第四，查redis sdk，這庫咱們維護的，看源碼，看實時棧，看是否有阻塞（sdk 用了pool，sdk 自己也要壓測下）；

第五，查看當前的gc pause ，看gc stw 時間是否影響redis（go 1.8 gc 性能比1.10-1.12 差不少）；

第六，抓trace ，看調度時間和調度時機是否有問題（併發協程數，GOMAXPROCS cpu負載都會影響調度）；

整個分析下來，只能用排除法了。

三， 現場分析

3.1 網絡分析

由於服務的併發量比較大，其實查起來很是耗時。

• 1， redis slowlog 自己是正常的。這裏相似相似redis， redis 有SLOWLOG。這裏感謝redis 團隊的支持。

• 2，咱們該抓包了，將日誌裏的key 跟tcpdump 的key 對起來。由於併發量很是大，tcpdump 出來的數據簡直無法看，這裏咱們線上dump，線下分析。

tcpdump 抓了幾分鐘時間。grep 日誌裏超時的case, 例如key 是rec_useraction_bg_2_user_319607672835 這個key 顯示126ms, 可是wireshark 顯示僅僅不到2ms。wireshark 如何找到這個包呢？

抓包顯示，一共請求兩次，來源端口分別是34442，34510， 時間是13:57，No 是261。接下來再找到兩次response 便可。

No.261 && port == 34442 的請求，最快的resp 以下：

分析了其餘的key，獲得的結論都相似，redis 返回很是快，根本沒什麼問題。

3.2 負載分析

是有cpu 監控的，惋惜的是，是宿主機的cpu監控。這裏cpu 佔用看，由於資源隔離，宿主機沒問題，可是這個進程的cpu 抖動比較厲害,iostat 顯示的狀況更真實。這裏經常使用40%，可是定時任務起起來的時候，接近所有打滿！抖動是否跟定時任務有關？但問了業務，其實相關性沒有那麼明顯。

3.3 redis sdk 問題排查

sdk 是存在阻塞的可能的，怎麼判斷sdk 是否阻塞了？兩個方式，一種是源碼級別追查，第二種是查看實時棧，看是否有lock，wait 之類的邏輯。初步看並無阻塞邏輯。dump了下線上的棧，看起來，也沒有什麼問題。但日誌確實顯示，到底怎麼回事？

這裏有個認知問題，有runtime 的語言，sdk 都是受runtime 影響的，sdk 寫的再好，並不能保證延時，好比你跑下下面這個demo。50個併發，你訪問redis 都各類超時。

package main

import (
	"flag"
	"fmt"
	"sync"
	"time"

	"net/http"
	_ "net/http/pprof"

	"github.com/gomodule/redigo/redis"
)

var redisAddr string

type Stu struct {
	Name string `json:"name"`
	Age  int
	HIgh bool
	sex  string
}

func main() {
	flag.StringVar(&redisAddr, "redis", "127.0.0.1:6379", "-redis use redis addr ")
	flag.Parse()
	go func() {
		http.ListenAndServe("0.0.0.0:8003", nil)
	}()

	wg := sync.WaitGroup{}
	wg.Add(1)
	for i := 0; i < 20; i++ {
		go go_get(wg)
	}

	wg.Wait()

}

func go_get(wg sync.WaitGroup) {
	client, err := redis.Dial("tcp", redisAddr)
	if err != nil {
		fmt.Println("connect redis error :", err)
		return
	}
	defer client.Close()
	for {
		time.Sleep(10 * time.Millisecond)
		start := time.Now()
		client.Do("GET", "test1234")
		if cost := time.Now().Sub(start); cost > 10*time.Millisecond {
			fmt.Printf("time cost %v \n", cost)
		}

	}
}

3.4 runtime gc 問題排查及優化

抓了下線上heap 圖，查看歷史的gc stw 信息:

curl http://localhost:8003/debug/pprof/heap?debug=1 -O heap

上面的數據，是歷史stw 時間，沒runtime 歷史監控只能看這了，數據簡直無法看，上面是個256的數組，單位是ns，循環寫入。gc 的策略通常主動觸發是2min一次，或者內存增加到閾值，先初步認爲2min一個點吧。gc 得必須得優化，可是跟日誌毛刺的密度比，還對不上。

查看具體的問題在哪，graph 以下：

大頭在兩個地方，一個是hmget， 一個是json。優化gc 的思路有不少，也不復雜，有實例，參考我我的博客：https://my.oschina.net/u/2950272/blog/1788299。最簡單有效的，你先把版本升下吧，起碼得升到1.10吧（其實最好1.12。1.8，1.9，1.10, 1.11我都踩過坑），高頻服務，1.8一個定時器問題你qps 就上不去了，示例參考：https://my.oschina.net/u/2950272/blog/2247104。

這裏是業務同窗升版本後的graph：

看下hmget 和json encode 的區別，如今大頭全在hmget 上了，效果立杆見影子。這裏爲啥hmget 這麼多？問了下，這是業務邏輯實現，這樣作是有問題的。不能影響業務，全部暫時做罷。只升級大版本，stw 好了不少，雖然偶爾也有幾十毫秒的毛刺，對比圖以下（單位ms）：

惋惜，問題並無解決，redis 的抖動沒有明顯變化：

爲何一直追這redis 查 ，不追着其餘接口查，由於redis 要求比較高，是ms 級別，其餘的api是百ms級別，毛刺就不明顯了。

目前看gc 問題其實還有優化空間，可是成本就高了，得源碼優化，改動會比較大，業務方不能接受。並且，當前的gc 大幅改善對接口耗時並沒起到立竿見影效果，這裏需從其餘方面尋找問題。

3.5，抓trace ，查看調用棧

curl http://127.0.0.1:8080/debug/pprof/trace?seconds=300 > trace.out
go tool trace trace.out

線上trace，記錄了採樣階段go 都在幹嗎，不過由於混合業務代碼，你想直接看圖，基本是不可能了，打開都得等幾分鐘（沒辦法，有業務邏輯）。。。

單獨看gc，和heap 之中數據基本一致。這裏問題比較嚴重的是調度，按scheduler wait 排序後數據以下：

加了監控後，看到其實併發的協程數量並不太多，也沒出現協程暴增的狀況，照理調度並不會這麼嚴重。

影響調度的，還有p 的數量目前是48（宿主機核心數，由於go 啓動讀了宿主機的核心），線程數是200+。線程數查看ps -T -p pid。8核上跑48個調度線程，會影響調度，這個影響很差評估，可是要優化。咱們建議將GOMAXPROC 設置成8，而後從新上線。而後抖動馬上降下來了，效果以下：

對比，當前的調度時間，雖然仍是有點難看，可是直接降了快接近一個數量級。

同時，pprof 顯示，目前的線程數，降到了之前的1/3。經過perf看線程的上下文切換也少了，同時調度自己也少了。

到此，問題基本查到根因，並解決了。

四，原理分析

爲何獲取到錯誤的cpu 數，會致使業務耗時增加這麼嚴重？主要仍是對延遲要求太敏感了，而後又是高頻服務，runtime 的影響被放大了。

關於怎麼解決獲取正確核數的問題，目前golang 服務的解決方式主要是兩個，第一，設置環境變量GOMAXPROCS 啓動，第二個是顯式調用uber/aotomaxprocs。

golang 是如何設置cpu 核數，並取成宿主的核數的呢，追runtime.NumCPU() 發現，其實現是：

細追，發現是 getproccount, 查linux 下源碼發現，其實調用的是 sched_getaffinity，直接經過系統調用獲取的宿主機核數。

uber/aotomaxprocs 是如何算正確的cpu 核數？其實就是讀取 cgroup 接口 /sys/fs/cgroup/cpu/cpu.cfs_quota_us 中的值除以 /sys/fs/cgroup/cpu/cpu.cfs_period_us 中的值並向上取整

這種問題，其實在golang runtime 就解決比較好，像java ，jdk （jdk8u191）之後，都已經能自適應容器和實體服務器了，不太明白爲何會有這種問題，去提個issue。

五， 總結

大部分的服務其實對延時可能沒這麼敏感，因此沒過重視這個問題。爲了不之後再出相似問題，咱們在流程上，但願能直接規避掉。咱們作的有三點：

第一，給全部go項目加上runtime 監控，若是真出大故障，有時間去臨時加pprof 嗎？

第二，在全部容器裏注入環境變量GOMAXPROCS，並算出cgroup 限制的核數。若是你們有需求自定義p的數量，能夠本身顯示調用。你們也可使用uber/aotomaxprocs。

第三，推進你們將線上go 版本升級，特別是高頻服務。