原创文章，转载请务必将下面这段话置于文章开头处（保留超链接）。
本文转发自[董泽润 blog]，不允许修改题目及内容原文链接
背景
项目重构，由 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 包？不应该随机么？
20170315
最近服务上线，流量逐步放多，api 发现超时越来越多，而我们的 granfa 监控也发现好多莫多其秒的超时。
很多外围 IO 超时或错误，比如 redis, 能达到 1 ~ 2 秒，完全不应该。
此时发现我们有逻辑打日志，日志库使用了 channel buffer 记录，初步怀疑 channel 满了，导致所有请求同步阻塞。
增加对日志库 channel 后，发现 1024 长度不够用，有时会突然被打满。为了测试，我们调大 channel， 并且如果满了就丢弃日志。上线后，发现还是很多超时...
20170316
两波人一起查，redis 同学抓包发现，程序 GC 期间 dial redis 的包没有发出去，还是因为 GC 搞的鬼...
但此时我们 curl pprof 接口，gc pause 时间很短，也就是 STW 很短，继续 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
从当前内存对象上来看，排第一的是模型文件加载函数，还有一个是 fmt.Sprintf 日志模块的。
go tool pprof bin/dupsdc http://127.0.0.1:6060/debug/pprof/profile
结合 cpu 使用，发现很大一部分消耗在 gc，由于 go1.7 的改动，虽然 gc STW 时间短了，但是 cpu 使用率上升，整个 gc 吞吐量下降了。
测试 go1.8
刚好前两个月 go1.8 GA 听说性能提升很大，在不改变现在代码的情况下直接用 go1.8 会提升性能，但是我们线上不支持，还得用 go1.7
优化对象个数
模型对象 map[int64][]float32, 就是 model.loadPassengerFeatures2.func2 函数生成的模型，将 []float32 改成数组 [6]float32，将另外一个模型的指针改成了值拷贝后，再次压测：
经过 pprof 发现，分配对象最多的是 thrift 底层，当前使用的对象也少很多，看不见模型了。通过 cpu profile 发现，排在第一的是 syscall，而 gc scan object 排在了后面，这才是常态，因方 IO 密集型的应该往往都卡在了网络或磁盘 IO，所以 syscall 才能排第一。
上线
在仿真环境压测，还是会发现偶尔耗时长的请求，最终上线后效果非常好，优化完毕。
