【5-3 Golang】实战—HTTP服务假死问题分析

tomato01 · · 563 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

## 问题描述 &emsp;&emsp;下午15点左右,QA反馈灰度环境大量请求超时。kibana查询灰度网关日志,确实存在部分请求响应时间超过60秒,HTTP状态码504。进一步分析日志,所有504请求的上游地址都是xxxx:80。 &emsp;&emsp;目前该服务部署了两套环境,k8s + kvm,k8s环境上游ingress(即Nginx)端口80,kvm环境上游Golang服务端口19001。是单单k8s环境服务有问题吗? &emsp;&emsp;登录到k8s服务终端,手动curl请求(healthCheck接口,没有复杂的业务处理,直接返回数据),发现请求没有任何响应,且一直阻塞。很大概率是该Golang服务有问题了。 ## 排查过程 &emsp;&emsp;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 ``` &emsp;&emsp;可以看到,三次握手成功,客户端发送了HTTP数据,服务端也正常返回ACk;但是没下文了,客户端等待60秒后,主动断开了连接。(Nginx配置:proxy_read_timeout=60秒)。 &emsp;&emsp;服务端接收到客户端请求为什么没有响应呢?可以dlv跟踪调试请求处理流程,看看是在哪一个环节阻塞了;另外,服务都开启了pprof,可以先看看当前服务的状态。 ``` curl http://localhost:xxxxx/debug/pprof/ <td>16391</td><td><a href=goroutine?debug&#61;1>goroutine</a></td> …… ``` &emsp;&emsp;协程数目非常多,有1.6w,而灰度环境目前流量已切走;理论上不应该存在这么多协程的。 &emsp;&emsp;继续使用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 ``` &emsp;&emsp;可以看到,大量协程在写日志(LogWrite)时候,阻塞了(管道写阻塞runtime.chansend),触发了协程切换。 ## 代码Review &emsp;&emsp;通过上面的排查,已经可以基本确认请求是阻塞在写日志这里了;下面需要排查下写日志为什么会阻塞请求呢。写日志的逻辑是这样的: ``` //写日志方法;只是写管道 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: } } } } ``` &emsp;&emsp;我们看到,HTTP处理请求,在写日志时候,调用LogWrite方法将日志写入管道。而在初始化FileLogTraceWriter时候,会启动子协程从管道中死循环读取日志数据。日志写入管道阻塞了,很有可能是这个子协程出异常了。 &emsp;&emsp;查找这两个子协程堆栈: ``` 1 runtime.gopark runtime.selectgo xxxxx/log4go.NewFileLogTraceWriter.func2 ``` &emsp;&emsp;NewFileLogTraceWriter.func2阻塞在select处;NewFileLogTraceWriter.func1协程不存在。 &emsp;&emsp;问题明白了,从管道中消费日志的子协程因为某些原因退出了。该协程有两处逻辑,在出现错误时候,直接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) } } } ``` &emsp;&emsp;最终,修改日志组件,每一个服务写日志时,都在日志文件后添加随机值,保证即使多个服务(pod)调度在同一个物理节点,也不会有冲突问题。当然子协程的错误处理机制也需要完善,提升子协程健壮性。 ## 非阻塞改造 &emsp;&emsp;HTTP请求处理协程,通过写管道方式写日志,就是为了不阻塞自己。但是发现,当管道消费者异常时候,还是会造成阻塞。web服务,写日志是必然的同时也是非必须的,如何才能保障写日志不会阻塞HTTP请求处理呢?其实写管道也可以是非阻塞方式的: &emsp;&emsp;有兴趣的可以查看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 } ``` &emsp;&emsp;查看Golang SDK源码,基于select可以实现管道的非阻塞读写(chanrecv与chansend函数,第三个参数标识是否阻塞当前协程)。另外,我们也可以稍加改造,实现管道带超时时间的读写。 ## 总结 &emsp;&emsp;在遇到Go程序阻塞问题,性能问题等任何异常时,记得结合前面介绍的pprof、trace、dlv等分析/调试工具。

有疑问加站长微信联系(非本文作者))

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889

563 次点击  ∙  1 赞  
加入收藏 微博
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传