Categories
程式開發

高頻 golang 服務接口超時排查以及性能調優


0. 目錄

  1. 背景
  2. 解決思路
  3. 現場分析
    網絡分析
    負載分析
    redis sdk 問題排查
    runtime 問題排查及優化
    抓trace ,查看調用棧
  4. 原理分析
  5. 總結

1. 背景

最近,策略組同學反饋有個服務上線後 redis 超時非常嚴重,嚴重到什麼地步呢,內網讀寫redis 毛刺超過100ms!而且不是隨機出現,非常多,而且均勻,導致整個接口超時嚴重。因為用的 redis 庫是由我們穩定性與業務中間件組維護,所以任務落我們組小伙伴頭上了。

這個項目有非常複雜的業務邏輯,然後要求接口在100 ms 左右能返回。這個服務有密集型 io(調度問題)+定時任務(cpu問題)+常駐內存 cache(gc問題)。頻繁訪問 redis,在定時邏輯中,業務邏輯一個 request 可能達到上千次 redis Hmget/Get (先不討論合理性)。複雜業務給問題排查帶來比較多干擾因素,這些因素都可能導致抖動。

go version : 1.8,機器是8核+16G 容器,沒有開 runtime 監控,redis 的同事初步反饋沒有 slowlog。因為rd 也追了很久,到我們這邊來的時候,redis 的超時指標監控已經給我們加了,每個key 的查詢都會打印日誌方便debug。

redis get 接口的耗時監控顯示如下,因為高頻請求,大部分耗時是小於10ms 的,但是這毛刺看著非常嚴重,是不可忍受了。

高頻 golang 服務接口超時排查以及性能調優 1

系統cpu問題比較嚴重,抖動非常大,內存並沒有太大問題,但是佔用有點大。因為用了local-cache,也可能引起 gc 問題。

高頻 golang 服務接口超時排查以及性能調優 2

高頻 golang 服務接口超時排查以及性能調優 3

因為沒有加 runtime 監控,其他信息暫不可知。

2. 解決思路

因為追查接口毛刺比較複雜,我們的原則是不影響業務的情況下,盡量少上線的將業務問題解決。

第一、首先排查是不是網絡問題,查一段時間的 redis slowlog(slowlog 最直接簡單);

第二、 本地抓包,看日誌中 redis 的 get key 網絡耗時跟日誌的時間是否對的上;

第三、查機器負載,是否對的上毛刺時間(彈性雲機器,宿主機情況比較複雜);

第四、查 redis sdk,這庫我們維護的,看源碼,看實時棧,看是否有阻塞(sdk 用了pool,pool 邏輯是否可能造成阻塞);

第五、查看 runtime 監控,看是否有協程暴增,看 gc stw 時間是否影響 redis(go 版本有點低,同時內存佔用大);

第六、抓 trace ,看調度時間和調度時機是否有問題(並發協程數,GOMAXPROCS cpu負載都會影響調度);

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

3. 現場分析

網絡分析

因為服務的並發量比較大,其實查起來非常耗時。

  1. redis slowlog 經查是正常的,顯示沒有超過10ms 的 get 請求。
  2. 我們該抓包了,將日誌裡的 key 跟 tcpdump 的 key 對起來。因為並發量非常大,tcpdump 出來的數據簡直沒法看,這裡我們線上 dump,線下分析。 tcpdump 抓了幾分鐘時間。 grep 日誌裡超時的case, 例如key 是rec_useraction_bg_2_user_319607672835 這個 key 顯示126ms, 但是 wireshark 顯示僅僅不到2ms。

高頻 golang 服務接口超時排查以及性能調優 4

高頻 golang 服務接口超時排查以及性能調優 5

分析了其他的 key,得到的結論都類似,redis 返回非常快,根本沒什麼問題。

負載分析

我們是有 cpu 監控的,可惜的是,是宿主機的 cpu 監控。這裡 cpu 佔用看,因為資源隔離,宿主機沒問題,但是這個進程的 cpu 抖動比較厲害,這裡常用40%,但是定時任務起起來的時候,接近全部打滿!抖動是否跟定時任務有關?但看監控,其實相關性沒有那麼明顯,redis 超時更頻繁。

高頻 golang 服務接口超時排查以及性能調優 6

redis sdk 問題排查

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

高頻 golang 服務接口超時排查以及性能調優 7

這裡有個認知問題,有runtime 的語言,sdk 都是受runtime 影響的,sdk 寫的再好,並不能保證延時,比如你跑下下面這個demo,50個並發,你訪問redis 都各種超時。程序的 runtime 我們也需要查下。

package main


import (
    "flag"
    "fmt"
    "net/http"
    _ "net/http/pprof"
    "sync"
    "time"


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


var redisAddr 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  10*time.Millisecond {
            fmt.Printf("time cost %v n", cost)
        }
    }
}

runtime 排查及優化

抓了下線上heap 圖,查看歷史的gc stw 信息:curl http://localhost:8003/debug/pprof/heap?debug=1

高頻 golang 服務接口超時排查以及性能調優 8

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

查看具體的問題在哪,graph 如下:

高頻 golang 服務接口超時排查以及性能調優 9

大頭在兩個地方,一個是 hmget, 一個是 json。優化 gc 的思路有很多,也不復雜,有實例,參考我個人博客。最簡單有效的,你先把版本升下吧,高頻服務,1.8一個定時器問題你qps 就上不去了,示例參考

這裡是業務同學升版本後的graph:

高頻 golang 服務接口超時排查以及性能調優 10

看下 hmget 和 json encode 的區別,現在大頭全在 hmget 上了,效果立杆見影。這里為啥 hmget 這麼多?問了下,這是業務邏輯實現,這樣做是有問題的。不能影響業務,所有暫時作罷。只升級大版本,stw 好了很多,雖然偶爾也有幾十毫秒的毛刺,對比圖如下(單位ms):

高頻 golang 服務接口超時排查以及性能調優 11

可惜,問題並沒有解決,redis 的抖動沒有明顯變化:

高頻 golang 服務接口超時排查以及性能調優 12

為什麼一直追這 redis 查 ,不追著其他接口查,因為 redis 要求比較高,是 ms 級別,其他的 api 是百 ms 級別,毛刺就不明顯了。

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

抓trace ,查看調用棧

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

go tool trace trace.out

線上trace,記錄了採樣階段go 都在幹嘛,不過因為混合業務代碼,你想直接看圖,基本是不可能了,打開都得等幾分鐘(沒辦法,有業務邏輯)…

高頻 golang 服務接口超時排查以及性能調優 13

高頻 golang 服務接口超時排查以及性能調優 14

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

高頻 golang 服務接口超時排查以及性能調優 15

影響調度的,主要是協程數量和線程數量。

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

高頻 golang 服務接口超時排查以及性能調優 16

線程數查看 ps -T -p pid,線程數是200+,這個數量很奇怪,有點超出預期,8核的容器,默認 p 是8,線程數超過 p 數量20多倍。而從 trace 圖上看 p 是48,看著是 go 獲取了物理機的核心數。線程數會影響調度,這個影響不好評估,但是要優化。我們建議將 GOMAXPROC 設置成8,然後重新上線。然後抖動立刻降下來了,效果如下:

高頻 golang 服務接口超時排查以及性能調優 17

同時,pprof 顯示,目前的線程數,降到了以前的1/3。通過perf看線程的上下文切換也少了,同時調度本身也少了。

高頻 golang 服務接口超時排查以及性能調優 18

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

4. 原理分析

為什麼獲取到錯誤的 cpu 數,會導致業務耗時增長這麼嚴重?主要還是對延遲要求太敏感了,然後又是高頻服務,runtime 的影響被放大了。

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

golang 是如何設置cpu 核數,並取成宿主的核數的呢,追runtime.NumCPU() 發現,其實現細追,發現是getproccount, 查linux 下源碼發現,其實調用的是sched_getaffinity,直接通過系統調用獲取的宿主機核數。

func getproccount() int32 {
    // This buffer is huge (8 kB) but we are on the system stack
    // and there should be plenty of space (64 kB).
    // Also this is a leaf, so we're not holding up the memory for long.
    // See golang.org/issue/11823.
    // The suggested behavior here is to keep trying with ever-larger
    // buffers, but we don't have a dynamic memory allocator at the
    // moment, so that's a bit tricky and seems like overkill.
    const maxCPUs = 64 * 1024
    var buf (maxCPUs / 8)byte
    r := sched_getaffinity(0, unsafe.Sizeof(buf), &buf(0))
    if r >= 1
        }
    }
    if n == 0 {
        n = 1
    }
    return n
}

uber/aotomaxprocs 是如何算正確的cpu 核數?讀取 cgroup 接口 /sys/fs/cgroup/cpu/cpu.cfs_quota_us ,然後除以 /sys/fs/cgroup/cpu/cpu.cfs_period_us 並向上取整:

// CPUQuota returns the CPU quota applied with the CPU cgroup controller.
// It is a result of `cpu.cfs_quota_us / cpu.cfs_period_us`. If the value of
// `cpu.cfs_quota_us` was not set (-1), the method returns `(-1, nil)`.
func (cg CGroups) CPUQuota() (float64, bool, error) {
    cpuCGroup, exists := cg(_cgroupSubsysCPU)
    if !exists {
        return -1, false, nil
    }


    cfsQuotaUs, err := cpuCGroup.readInt(_cgroupCPUCFSQuotaUsParam)
    if defined := cfsQuotaUs > 0; err != nil || !defined {
        return -1, defined, err
    }

    cfsPeriodUs, err := cpuCGroup.readInt(_cgroupCPUCFSPeriodUsParam)
if err != nil {
        return -1, false, err
    }

    return float64(cfsQuotaUs) / float64(cfsPeriodUs), true, nil

}

像java ,jdk8u191 以後,都已經能自適應容器和實體服務器了,go 也應該考慮考慮自適應容器核數,畢竟是容器時代。

##5. 總結

這個問題排查優化結束了,但怎麼讓公司其他項目受益?

我們怎麼解決其他項目線上線下容器獲取錯 cpu 數的問題?現在很多項目沒開 runtime 監控,線上異常,怎麼方便定位問題?這個項目本身還有哪些可以優化的?等等。

第一個問題,我們在鏡像裡註入環境變量 GOMAXPROCS,並算出 cgroup 限制的核數。如果大家有需求自定義 p 的數量,可以自己顯式調用 https://github.com/uber-go/automaxprocs 。鏡像注入環境變量,相當於無感幫大家解決了獲取錯 cpu 的問題。

第二個問題,給我們部門 go 項目加上 runtime 監控,定時上報 runtime 信息同時提供採集pprof 能力。

第三個問題,優化 redis sdk hmget 函數,減少對象分配,業務流程也使用 pipeline 模式,合併 io。

作者介紹

萬鼎銘

滴滴 | 高級軟件開發工程師

本文轉載自公眾號滴滴技術(ID:didi_tech)。

原文鏈接

https://mp.weixin.qq.com/s?__biz=MzI1NDA3NzY4NA==&mid=2247486007&idx=2&sn=b5d177963dfa208aea834545d76ea230&chksm=e9cbf5acdebc7cbab0b795002d412c48e80b251fc390bc761260caeddefce384d73637256991&scene=27#wechat_redirect