共计 4084 个字符,预计需要花费 11 分钟才能阅读完成。
问题形容
下午 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 等剖析 / 调试工具。