## 问题描述
  下午15点左右，QA反馈灰度环境大量请求超时。kibana查询灰度网关日志，确实存在部分请求响应时间超过60秒，HTTP状态码504。进一步分析日志，所有504请求的上游地址都是xxxx:80。
  目前该服务部署了两套环境，k8s + kvm，k8s环境上游ingress（即Nginx）端口80，kvm环境上游Golang服务端口19001。是单单k8s环境服务有问题吗？
  登录到k8s服务终端，手动curl请求（healthCheck接口，没有复杂的业务处理，直接返回数据），发现请求没有任何响应，且一直阻塞。很大概率是该Golang服务有问题了。
## 排查过程
  healthCheck接口逻辑非常的简单，为什么会阻塞呢？服务没有接收到该请求吗？tcpdump抓包看看：
```
//xxxx为k8s入口ingress地址
curl http://xxxx/v1/healthCheck -H "Host:xxxxxxx"
//三次握手
10:20:21.940968 IP xxxx.40970 > server.19001: Flags [S], seq 3201212889, win 29200, length 0
10:20:21.941003 IP server.19001 > xxxx.40970: Flags [S.], seq 1905160768, ack 3201212890, win 28960, length 0
10:20:21.941175 IP xxxx.40970 > server.19001: Flags [.], ack 1905160769, win 58, length 0
//发送HTTP请求数据
10:20:21.941219 IP xxxx.40970 > server.19001: Flags [P.], seq 3201212890:3201213201, ack 1905160769, win 58, length 311
10:20:21.941223 IP server.19001 > xxxx.40970: Flags [.], ack 3201213201, win 59, length 0
//客户端主动断开连接
10:21:21.945740 IP xxxx.40970 > server.19001: Flags [F.], seq 3201213201, ack 1905160769, win 58, length 0
10:21:21.985062 IP server.19001 > xxxx.40970: Flags [.], ack 3201213202, win 59, length 0
```
  可以看到，三次握手成功，客户端发送了HTTP数据，服务端也正常返回ACk；但是没下文了，客户端等待60秒后，主动断开了连接。（Nginx配置：proxy_read_timeout=60秒）。
  服务端接收到客户端请求为什么没有响应呢？可以dlv跟踪调试请求处理流程，看看是在哪一个环节阻塞了；另外，服务都开启了pprof，可以先看看当前服务的状态。
```
curl http://localhost:xxxxx/debug/pprof/
<td>16391</td><td><a href=goroutine?debug=1>goroutine</a></td>
……
```
  协程数目非常多，有1.6w，而灰度环境目前流量已切走；理论上不应该存在这么多协程的。
  继续使用pprof查看协程统计详细信息：
```
go tool pprof http://localhost:xxxxx/debug/pprof/goroutine
(pprof) traces
----------+-------------------------------------------------------
7978 runtime.gopark
runtime.goparkunlock
runtime.chansend
runtime.chansend1
xxxxx/log4go.(*FileLogTraceWriter).LogWrite
xxxxx/log4go.Logger.LogTraceMap
xxxxx/log4go.LogTraceMap
xxxxx/builders.(*TraceBuilder).LoggerX
xxxxx/xesLogger.Ix
xxxxx/middleware.Logger.func1
github.com/gin-gonic/gin.(*Context).Next
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
github.com/gin-gonic/gin.(*Engine).ServeHTTP
net/http.serverHandler.ServeHTTP
net/http.(*conn).serve
```
  可以看到，大量协程在写日志（LogWrite）时候，阻塞了（管道写阻塞runtime.chansend），触发了协程切换。
## 代码Review
  通过上面的排查，已经可以基本确认请求是阻塞在写日志这里了；下面需要排查下写日志为什么会阻塞请求呢。写日志的逻辑是这样的：
```
//写日志方法；只是写管道
func (w *FileLogTraceWriter) LogWrite(rec *LogRecord) {
w.rec <- rec
}
func NewFileLogTraceWriter(fname string, rotate bool) *FileLogTraceWriter {
//子协程，从管道读取数据写入buffer
go func() {
for {
select {
case rec, ok := <-w.rec:
}
}
}
//子协程，从buffer读取数据写入文件
go func() {
for {
select {
case lb, ok := <-w.out:
}
}
}
}
```
  我们看到，HTTP处理请求，在写日志时候，调用LogWrite方法将日志写入管道。而在初始化FileLogTraceWriter时候，会启动子协程从管道中死循环读取日志数据。日志写入管道阻塞了，很有可能是这个子协程出异常了。
  查找这两个子协程堆栈：
```
1 runtime.gopark
runtime.selectgo
xxxxx/log4go.NewFileLogTraceWriter.func2
```
  NewFileLogTraceWriter.func2阻塞在select处；NewFileLogTraceWriter.func1协程不存在。
  问题明白了，从管道中消费日志的子协程因为某些原因退出了。该协程有两处逻辑，在出现错误时候，直接return，会导致协程的结束。经过进一步定位排查发现，原来是日志滚动造成的：某一段时间两个服务（pod）调度在同一台物理节点上，日志文件路径+名称一致，并且开启了定时切割，某一时刻同时rename日志文件，这时候只有一个服务rename日志文件成功，其他的rename日志文件都会出现源文件不存在错误，导致该协程退出（return）：
```
func NewFileLogWriter(fname string, rotate bool) *FileLogWriter {
for {
select {
case <-w.rot:
//滚动报错return，协程退出
if err := w.intRotate(); err != nil {
fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.filename, err)
return
}
}
}
func (w *FileLogWriter) intRotate() error {
if w.rotate {
//报错源文件不存在
err = os.Rename(w.filename, fname)
if err != nil {
return fmt.Errorf("Rotate: %s\n", err)
}
}
}
```
  最终，修改日志组件，每一个服务写日志时，都在日志文件后添加随机值，保证即使多个服务（pod）调度在同一个物理节点，也不会有冲突问题。当然子协程的错误处理机制也需要完善，提升子协程健壮性。
## 非阻塞改造
  HTTP请求处理协程，通过写管道方式写日志，就是为了不阻塞自己。但是发现，当管道消费者异常时候，还是会造成阻塞。web服务，写日志是必然的同时也是非必须的，如何才能保障写日志不会阻塞HTTP请求处理呢？其实写管道也可以是非阻塞方式的：
  有兴趣的可以查看runtime/chan.go文件学习。
```
// 非阻塞写实现
// compiler implements
//
// select {
// case c <- v:
// ... foo
// default:
// ... bar
// }
//
// as
//
// if selectnbsend(c, v) {
// ... foo
// } else {
// ... bar
// }
//
func selectnbsend(c *hchan, elem unsafe.Pointer) (selected bool) {
return chansend(c, elem, false, getcallerpc())
}
// 非阻塞读实现
//compiler implements
//
// select {
// case v = <-c:
// ... foo
// default:
// ... bar
// }
//
// as
//
// if selectnbrecv(&v, c) {
// ... foo
// } else {
// ... bar
// }
//
func selectnbrecv(elem unsafe.Pointer, c *hchan) (selected bool) {
selected, _ = chanrecv(c, elem, false)
return
}
```
  查看Golang SDK源码，基于select可以实现管道的非阻塞读写（chanrecv与chansend函数，第三个参数标识是否阻塞当前协程）。另外，我们也可以稍加改造，实现管道带超时时间的读写。
## 总结
  在遇到Go程序阻塞问题，性能问题等任何异常时，记得结合前面介绍的pprof、trace、dlv等分析/调试工具。
有疑问加站长微信联系（非本文作者））
