原創(chuàng)文章，轉(zhuǎn)載請務(wù)必將下面這段話置于文章開頭處（保留超鏈接）。
本文轉(zhuǎn)發(fā)自[董澤潤 blog]，不允許修改題目及內(nèi)容原文鏈接
背景
項(xiàng)目重構(gòu)，由 C++ 轉(zhuǎn)到 Golang, 發(fā)現(xiàn)對一個緩存操作有毛刺，時不時響應(yīng)時間到1s，或是 2s，正常平峰期基本不大于 10ms。
緩存支持方排查
找到緩存同學(xué)，他們的曲線圖顯示，所有請求均正常反回，在高峰期會有重試，平均耗時增大，但很少大于 100ms 的。那么問題來了，難道是網(wǎng)絡(luò)問題？
仔細(xì)想想，網(wǎng)絡(luò)問題一般都是交換機(jī)導(dǎo)致的，不可能只有我們有這現(xiàn)象，并且是偶而的，不是規(guī)律性的毛刺。排除緩存自身。
設(shè)置超時時間為什么不起作用？
查看配置發(fā)現(xiàn)我們代碼寫錯了，緩存的超時時間配置成了另外一個依賴的時間，最大是 2s ...
fix 后在仿真環(huán)境調(diào)試，仍然出現(xiàn)響應(yīng)大于 1s 的現(xiàn)象，也就是 SetReadDeadline 沒有限制住。這時候查 bug 開始跑偏：懷疑 thrift golang 庫問題。
thrift golang 超時調(diào)用方式
項(xiàng)目沒用 context 去做接口超時控制，而是用 thrift SetTimeout。查看代碼發(fā)現(xiàn)邏輯有問題，或是我們理解偏差。
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)
}
可以發(fā)現(xiàn)，timeout 是針對單個 tcp socket 操作，而不是接口層面。返回包較大時，每次 tcp read 都會重置 timeout，在此猜測多個 tcp read 超時時間累加導(dǎo)致超時失效。
此時想用 context 限制接口超時。。。
繼續(xù)查每次 tcp read 耗時
打印單次接口耗時
統(tǒng)計(jì)發(fā)現(xiàn)都是第一個 tcp read 時間長，基本都是 900ms 左右。thrift 底層操作，先 write 請求到 socket, 然后立馬 read socket，runtime 會將 read 掛起扔到 epoll 等待有事件生成。難道 SetReadDeadline 不生效？
換成 go1.7
查到最后發(fā)現(xiàn)仿真環(huán)境是 go1.4，線上是 go1.7，將仿真環(huán)境用 1.7 編譯后，響應(yīng)時間正常，并且 socket timeout 正常生效。所以第一反應(yīng)是 go1.4 極端情況的bug???
GC 才是問題
通過查看 gc 時間和發(fā)生時間點(diǎn)，發(fā)現(xiàn)真正的元兇是 gc...
業(yè)務(wù)有大量模型加載，使用大量的 map ，內(nèi)存對象很多，gc 在go1.4時很大，也沒做優(yōu)化。
整個排查過程很沒有頭緒，生產(chǎn)環(huán)境和仿真環(huán)境版本不一致，配置代碼寫錯，導(dǎo)致整個過程很低效，不過也發(fā)現(xiàn) thrift go timeout 的問題。
最終方案???
不用 context 做接口超時，thrift go 代碼也不改，因?yàn)槲覀兌际嵌踢B接，默認(rèn)情況第一個包限制超時就好，后續(xù) tcp 包都很快。
但是，go1.4 STW 時為什么只掛起了第一個 tcp 包？不應(yīng)該隨機(jī)么？
20170315
最近服務(wù)上線，流量逐步放多，api 發(fā)現(xiàn)超時越來越多，而我們的 granfa 監(jiān)控也發(fā)現(xiàn)好多莫多其秒的超時。
很多外圍 IO 超時或錯誤，比如 redis, 能達(dá)到 1 ~ 2 秒，完全不應(yīng)該。
此時發(fā)現(xiàn)我們有邏輯打日志，日志庫使用了 channel buffer 記錄，初步懷疑 channel 滿了，導(dǎo)致所有請求同步阻塞。
增加對日志庫 channel 后，發(fā)現(xiàn) 1024 長度不夠用，有時會突然被打滿。為了測試，我們調(diào)大 channel， 并且如果滿了就丟棄日志。上線后，發(fā)現(xiàn)還是很多超時...
20170316
兩波人一起查，redis 同學(xué)抓包發(fā)現(xiàn)，程序 GC 期間 dial redis 的包沒有發(fā)出去，還是因?yàn)?GC 搞的鬼...
但此時我們 curl pprof 接口，gc pause 時間很短，也就是 STW 很短，繼續(xù) pprof 查看：
go tool pprof -alloc_objects http://127.0.0.1:6060/debug/pprof/heap
go tool pprof -inuse_objects http://127.0.0.1:6060/debug/pprof/heap
從當(dāng)前內(nèi)存對象上來看，排第一的是模型文件加載函數(shù)，還有一個是 fmt.Sprintf 日志模塊的。
go tool pprof bin/dupsdc http://127.0.0.1:6060/debug/pprof/profile
結(jié)合 cpu 使用，發(fā)現(xiàn)很大一部分消耗在 gc，由于 go1.7 的改動，雖然 gc STW 時間短了，但是 cpu 使用率上升，整個 gc 吞吐量下降了。
測試 go1.8
剛好前兩個月 go1.8 GA 聽說性能提升很大，在不改變現(xiàn)在代碼的情況下直接用 go1.8 會提升性能，但是我們線上不支持，還得用 go1.7
優(yōu)化對象個數(shù)
模型對象 map[int64][]float32, 就是 model.loadPassengerFeatures2.func2 函數(shù)生成的模型，將 []float32 改成數(shù)組 [6]float32，將另外一個模型的指針改成了值拷貝后，再次壓測：
經(jīng)過 pprof 發(fā)現(xiàn)，分配對象最多的是 thrift 底層，當(dāng)前使用的對象也少很多，看不見模型了。通過 cpu profile 發(fā)現(xiàn)，排在第一的是 syscall，而 gc scan object 排在了后面，這才是常態(tài)，因方 IO 密集型的應(yīng)該往往都卡在了網(wǎng)絡(luò)或磁盤 IO，所以 syscall 才能排第一。
上線
在仿真環(huán)境壓測，還是會發(fā)現(xiàn)偶爾耗時長的請求，最終上線后效果非常好，優(yōu)化完畢。
