記一次GC引起的問題排查

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

背景

項目重構，由 C++ 轉到 Golang, 發現對一個快取作業有毛刺，時不時回應時間到1s，或是 2s，正常平峰期基本不大於 10ms。

線上IO.png

現象如，問題很簡單，排查過程很混亂。還是太年輕...

緩衝支援方排查

找到緩衝同學，他們的曲線圖顯示，所有請求均正常反回，在高峰期會有重試，平均耗時增大，但很少大於 100ms 的。那麼問題來了，難道是網路問題？

仔細想想，網路問題一般都是交換器導致的，不可能只有我們有這現象，並且是偶而的，不是規律性的毛刺。排除緩衝自身。

設定逾時時間為什麼不起作用？

查看配置發現我們代碼寫錯了，緩衝的逾時時間配置成了另外一個依賴的時間，最大是 2s ...

fix 後在模擬環境調試，仍然出現響應大於 1s 的現象，也就是 SetReadDeadline 沒有限制住。這時候查 bug 開始跑偏：懷疑 thrift golang 庫問題。

thrift golang 逾時調用方式

項目沒用 context 去做介面逾時控制，而是用 thrift SetTimeout。查看代碼發現邏輯有問題，或是我們理解偏差。

func (p *TSocket) pushDeadline(read, write bool) {    var t time.Time    if p.timeout > 0 {        t = time.Now().Add(time.Duration(p.timeout))    }    if read && write {        p.conn.SetDeadline(t)    } else if read {        p.conn.SetReadDeadline(t)    } else if write {        p.conn.SetWriteDeadline(t)    }}func (p *TSocket) Read(buf []byte) (int, error) {    if !p.IsOpen() {        return 0, NewTTransportException(NOT_OPEN, "Connection not open")    }    p.pushDeadline(true, false)    n, err := p.conn.Read(buf)    return n, NewTTransportExceptionFromError(err)}func (p *TSocket) Write(buf []byte) (int, error) {    if !p.IsOpen() {        return 0, NewTTransportException(NOT_OPEN, "Connection not open")    }    p.pushDeadline(false, true)    return p.conn.Write(buf)}

可以發現，timeout 是針對單個 tcp socket 操作，而不是介面層面。返回包較大時，每次 tcp read 都會重設 timeout，在此猜測多個 tcp read 逾時時間累加導致逾時失效。

此時想用 context 限制介面逾時。。。

繼續查每次 tcp read 耗時

列印單次介面耗時

socket.go read耗時

統計發現都是第一個 tcp read 時間長，基本都是 900ms 左右。thrift 底層操作，先 write 請求到 socket, 然後立馬 read socket，runtime 會將 read 掛起扔到 epoll 等待有事件產生。難道 SetReadDeadline 不生效？

換成 go1.7

查到最後發現模擬環境是 go1.4，線上是 go1.7，將模擬環境用 1.7 編譯後，回應時間正常，並且 socket timeout 正常生效。所以第一反應是 go1.4 極端情況的bug???

GC 才是問題

通過查看 gc 時間和發生時間點，發現真正的元兇是 gc...
業務有大量模型載入，使用大量的 map ，記憶體對象很多，gc 在go1.4時很大，也沒做最佳化。

GC

整個排查過程很沒有頭緒，生產環境和模擬環境版本不一致，配置代碼寫錯，導致整個過程很低效，不過也發現 thrift go timeout 的問題。

最終方案

不用 context 做介面逾時，thrift go 代碼也不改，因為我們都是短串連，預設情況第一個包限制逾時就好，後續 tcp 包都很快。

但是，go1.4 STW 時為什麼只掛起了第一個 tcp 包？不應該隨機嗎？