之前在這篇無人值守（一）^[1]簡(jiǎn)單介紹了我們針對(duì)線上抖動(dòng)問題定位的工具的設(shè)計(jì)思路，思路很簡(jiǎn)單，技術(shù)含量很低，是個(gè)人都可以想得到，但是它確實(shí)幫我們查到了很多很難定位的問題。

在本篇里，我們重點(diǎn)講一講這個(gè)工具^[2]在生產(chǎn)環(huán)境幫我們發(fā)現(xiàn)了哪些問題。

OOM 類問題

RPC decode 未做防御性編程，導(dǎo)致 OOM

應(yīng)用側(cè)的編解碼可能是非官方實(shí)現(xiàn)(如 node 之類的無官方 SDK 的項(xiàng)目)，在一些私有協(xié)議 decode 工程中會(huì)讀諸如 list len 之類的字段，如果外部編碼實(shí)現(xiàn)有問題，發(fā)生了字節(jié)錯(cuò)位，就可能會(huì)讀出一個(gè)很大的值。

非標(biāo)準(zhǔn) app ----encode-------> 我們的應(yīng)用 decode -----> Boom!

decoder 實(shí)現(xiàn)都是需要考慮這種情況的，類似這樣^[3]。如果對(duì)請(qǐng)求方的數(shù)據(jù)完全信任，碰到對(duì)方的 bug 或者惡意攻擊，可能導(dǎo)致自己的服務(wù) OOM。

在線上實(shí)際發(fā)現(xiàn)了一例內(nèi)存瞬間飚升的 case，收到報(bào)警后，我們可以看到：

1:?1330208768?[1:?1330208768]?@?0x11b1df3?0x11b1bcb?0x119664e?0x11b1695?0x1196f77?0x11a956a?0x11a86c7?0x1196724?0x11b1695?0x11b1c29?0x119664e?0x11b1695?0x11b1c29?0x119664e?0x11b1695?0x11b1c29?0x119664e?0x11bb360?0x168f143?0x179c2fc?0x1799b70?0x179acd6?0x16d3306?0x16d1088?0xf59386?0xf59474?0xf54e5f?0xf54987?0xf539f1?0xf6043a?0xcd8c0d?0x49b481 ....下面是表示棧內(nèi)容的，這不重要

1: 1330208768 [1: 1330208768] 表示 inuse_objects : inuse_space [alloc_objects : alloc_space]，這里可以看到一個(gè)對(duì)象就直接用掉了 1GB 內(nèi)存，顯然不是正常情況，查看代碼后，發(fā)現(xiàn)有未進(jìn)行大小判斷而完全信任用戶輸入數(shù)據(jù)包的 decode 代碼。

修復(fù)起來很簡(jiǎn)單，像前面提到的 async-h1 一樣加個(gè)判斷就可以了。

tls 開啟后線上進(jìn)程占用內(nèi)存上漲，直至 OOM

線上需要做全鏈路加密，所以有開啟 tls 的需求，但開啟之后發(fā)現(xiàn)內(nèi)存一路暴漲，直至 OOM，工具可以打印如下堆棧：

heap?profile:?1460:?27614136?[45557:?1080481472]?@?heap/1048576 727:?23822336?[730:?23920640]?@?0xc56b96?0xc591e8?0xc58e68?0xc59ed1?0xdd55ff?0xde15b8?0xde13ef?0xde09e9?0xde050c?0x13bfa13?0x13bf475?0x14c33d0?0x14c49f8?0x14cb398?0x14bffab?0x14cdf78?0xddcf90?0x45eda1 #?0xc56b95??*****mtls/crypto/tls.(*block).reserve+0x75???*****mtls/crypto/tls/conn.go:475

查閱老版本的 Go 代碼，發(fā)現(xiàn)其 TLS 的 write buffer 會(huì)隨著寫出的數(shù)據(jù)包大小增加而逐漸擴(kuò)容，其擴(kuò)容邏輯比較簡(jiǎn)單：

func?(b?*block)?reserve(n?int)?{if?cap(b.data)?>=?n?{return}m?:=?cap(b.data)if?m?==?0?{m?=?1024}for?m?<?n?{m?*=?2}data?:=?make([]byte,?len(b.data),?m)copy(data,?b.data)b.data?=?data }

初始為 1024，后續(xù)不夠用每次擴(kuò)容為兩倍。但是閱讀 tls 的代碼后得知，這個(gè)寫出的數(shù)據(jù)包大小最大實(shí)際上只有 16KB + 額外的一個(gè)小 header 大小左右，但老版本的實(shí)現(xiàn)會(huì)導(dǎo)致比較多的空間浪費(fèi)，因?yàn)樽罱K會(huì)擴(kuò)容到 32KB。

這段比較浪費(fèi)空間的邏輯在 Go1.12 之后已經(jīng)進(jìn)行了優(yōu)化：

func?sliceForAppend(in?[]byte,?n?int)?(head,?tail?[]byte)?{if?total?:=?len(in)?+?n;?cap(in)?>=?total?{head?=?in[:total]}?else?{head?=?make([]byte,?total)copy(head,?in)}tail?=?head[len(in):]return }

變成了需要多少，分配多少的樸實(shí)邏輯。所以會(huì)比老版本在這個(gè)問題上有不少緩解，不過在我們的場(chǎng)景下，新版本的代碼依然沒法滿足需求，所以還需要進(jìn)一步優(yōu)化，這就是后話了。

goroutine 暴漲類問題

本地 app GC hang 死，導(dǎo)致 goroutine 卡 channel send

在我們的程序中有一段和本地進(jìn)程通信的邏輯，write goroutine 會(huì)向一個(gè) channel 中寫數(shù)據(jù)，按常理來講，同物理機(jī)的兩個(gè)進(jìn)程通過網(wǎng)絡(luò)通信成本比較低，類似下面的代碼按說不太可能出問題：

concurrently: taskChan?<-?taskconsumer: for?task?:=?range?taskChan?{//?憋一些?task?一起寫localConnection.write(task?們) }

看起來問題不大，但是線上經(jīng)常都有和這個(gè) channel send 相關(guān)的抖動(dòng)，我們通過工具拿到的現(xiàn)場(chǎng)：

2020-11-03?08:00:05,950?[ERROR]?[diag.goroutine]?[diagnose]?pprof?goroutine,?config_min?:?3000,?config_diff?:?25,?config_abs?:?200000,??previous?:?[41402?44257?47247?50085?52795?55509?29762?32575?35451?38460],?current?:?55509,?profile?:?goroutine?profile:?total?55513 40844?@?0x46daaf?0x4433ab?0x443381?0x443165?0xf551f7?0x12fd2e7?0x12fc94f?0x13f41d5?0x13fc45f?0xf43ee4?0xcd8c0d?0x49b481 #????****channel.Send?這是個(gè)假的棧，你理解意思就行了 #?

當(dāng)前憋了 5w 個(gè) goroutine，有 4w 個(gè)卡在 channel send 上，這個(gè) channel 的對(duì)面還是一條本地連接，令人難以接受。

但是要考慮到，線上的業(yè)務(wù)系統(tǒng)是 Java，Java 發(fā)生 FG? 的時(shí)候可不是鬧著玩的。對(duì)往本地連接的 write buffer 寫數(shù)據(jù)一定不會(huì)卡的假設(shè)是有問題的。

既然出問題了，說明在這里對(duì)我們的程序進(jìn)行保護(hù)是必要的，修改起來也很簡(jiǎn)單，給 channel send 加一個(gè)超時(shí)就可以了。

應(yīng)用邏輯死鎖，導(dǎo)致連接不可用，大量 goroutine 阻塞在 lock 上

大多數(shù)網(wǎng)絡(luò)程序里，我們需要在發(fā)送應(yīng)用層心跳，以保證在一些異常情況(比如拔網(wǎng)線)下，能夠把那些無效連接從連接池里剔除掉。

對(duì)于我們的場(chǎng)景來說，客戶端向外創(chuàng)建的連接，如果一直沒有請(qǐng)求，那么每隔一段時(shí)間會(huì)向外發(fā)送一個(gè)應(yīng)用心跳請(qǐng)求，如果心跳連續(xù)失敗(超時(shí)) N 次，那么將該連接進(jìn)行關(guān)閉。

在這個(gè)場(chǎng)景下會(huì)涉及到兩把鎖：

• 對(duì)連接進(jìn)行操作的鎖 conn lock

• 記錄心跳請(qǐng)求的 request map lock

心跳成功的流程：收到心跳響應(yīng)包，獲取 conn lock -> 獲取 request map lock 心跳失敗的流程：timer 超時(shí)，獲取 request map lock -> 需要關(guān)閉連接 -> 獲取 conn lock

可以看出來，心跳的成功和失敗流程并發(fā)時(shí)，獲取鎖的流程符合死鎖的一般定義：持有鎖、非搶占、循環(huán)等待。

這個(gè) bug 比較難觸發(fā)，因?yàn)樾奶∫?N 次才會(huì)關(guān)閉連接，而正好在最后一次發(fā)生了心跳成功和失敗并發(fā)才會(huì)觸發(fā)上述的死鎖，線上可以通過 goroutine 短時(shí)間的上漲發(fā)現(xiàn)這個(gè)問題，goroutine 的現(xiàn)場(chǎng)也是可以看得到的。簡(jiǎn)單分析就可以發(fā)現(xiàn)這個(gè)死鎖問題(因?yàn)楹罄m(xù)的流程都會(huì)卡在其中一把鎖上)。

知道原因解決起來就不麻煩了，涉及到一些具體的業(yè)務(wù)邏輯，這里就不贅述了。

CPU 尖刺問題

應(yīng)用邏輯導(dǎo)致死循環(huán)問題

國(guó)際化業(yè)務(wù)涉及到冬夏令時(shí)的切換，從夏令時(shí)切換到冬令時(shí)，會(huì)將時(shí)鐘向前拔一個(gè)月，但天級(jí)日志輪轉(zhuǎn)時(shí)，會(huì)根據(jù)輪轉(zhuǎn)前的時(shí)間計(jì)算 24 小時(shí)后的時(shí)間，并按與 24:00 的差值來進(jìn)行 time.Sleep，這時(shí)會(huì)發(fā)現(xiàn)整個(gè)應(yīng)用的 CPU 飚高。自動(dòng)采樣結(jié)果發(fā)現(xiàn)一直在循環(huán)計(jì)算時(shí)間和重命名文件。

list 一下相關(guān)的函數(shù)，能很快地發(fā)現(xiàn)執(zhí)行死循環(huán)的代碼位置。這里就不截真實(shí)代碼了，隨便舉個(gè)例子：

????????.??????????.?????23:func?cpuex(wr?http.ResponseWriter,?req?*http.Request)?{.??????????.?????24:?go?func()?{17.73s?????19.37s?????25:??for?{.??????????.?????26:??}.??????????.?????27:?}().??????????.?????28:}

參考資料

[1]

無人值守（上）: https://xargin.com/autodumper-for-go/

[2]

工具: https://github.com/mosn/holmes

[3]

這樣: https://github.com/http-rs/async-h1/blob/main/src/server/decode.rs#L41

超強(qiáng)干貨來襲 云風(fēng)專訪：近40年碼齡，通宵達(dá)旦的技術(shù)人生

總結(jié)

以上是生活随笔為你收集整理的无人值守的自动 dump（二）的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。