背景
项目重构,由 C++ 转到 Golang, 发现对一个缓存操作有毛刺,时不时响应时间到1s,或是 2s,正常平峰期基本不大于 10ms。
现象如上图,问题很简单,排查过程很混乱。还是太年轻...
缓存支持方排查
找到缓存同学,他们的曲线图显示,所有请求均正常反回,在高峰期会有重试,平均耗时增大,但很少大于 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 耗时
打印单次接口耗时
统计发现都是第一个 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时很大,也没做优化。
整个排查过程很没有头绪,生产环境和仿真环境版本不一致,配置代码写错,导致整个过程很低效,不过也发现 thrift go timeout 的问题。
最终方案
不用 context 做接口超时,thrift go 代码也不改,因为我们都是短连接,默认情况第一个包限制超时就好,后续 tcp 包都很快。
但是,go1.4 STW 时为什么只挂起了第一个 tcp 包?不应该随机么?
有疑问加站长微信联系(非本文作者)