问题形容

  下午15点左右,QA反馈灰度环境大量申请超时。kibana查问灰度网关日志,的确存在局部申请响应工夫超过60秒,HTTP状态码504。进一步剖析日志,所有504申请的上游地址都是xxxx:80。

  目前该服务部署了两套环境,k8s + kvm,k8s环境上游ingress(即Nginx)端口80,kvm环境上游Golang服务端口19001。且,k8s环境该服务只部署一个pod。是单单k8s环境服务有问题吗?

  登录到k8s服务终端,手动curl申请(healthCheck接口,没有简单的业务解决,间接返回数据),发现申请没有任何响应,且始终阻塞。很大概率是该Golang服务有问题了。

排查过程

  healthCheck接口逻辑十分的简略,为什么会阻塞呢?服务没有接管到该申请吗?tcpdump抓包看看:

//xxxx为k8s入口ingress地址curl http://xxxx/v1/healthCheck -H "Host:studentlive.xueersi.com"//三次握手10:20:21.940968 IP xxxx.40970 > server.19001: Flags [S], seq 3201212889, win 29200, length 010:20:21.941003 IP server.19001 > xxxx.40970: Flags [S.], seq 1905160768, ack 3201212890, win 28960, length 010: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 31110: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 010: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:17009/debug/pprof/<td>16391</td><td><a href=goroutine?debug&#61;1>goroutine</a></td>……

  协程数目十分多,有1.6w,而灰度环境目前流量已切走;实践上不应该存在这么多协程的。

  持续应用pprof查看协程统计详细信息:

go tool pprof http://localhost:17009/debug/pprof/goroutine(pprof) traces----------+-------------------------------------------------------7978 runtime.gopark     runtime.goparkunlock     runtime.chansend     runtime.chansend1     git.100tal.com/wangxiao_go_lib/xesLogger/log4go.(*FileLogTraceWriter).LogWrite     git.100tal.com/wangxiao_go_lib/xesLogger/log4go.Logger.LogTraceMap     git.100tal.com/wangxiao_go_lib/xesLogger/log4go.LogTraceMap     git.100tal.com/wangxiao_go_lib/xesLogger/builders.(*TraceBuilder).LoggerX     git.100tal.com/wangxiao_go_lib/xesLogger.Ix     git.100tal.com/wangxiao_go_lib/xesGoKit/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    git.100tal.com/wangxiao_go_lib/xesLogger/log4go.NewFileLogTraceWriter.func2

  NewFileLogTraceWriter.func2阻塞在select处;NewFileLogTraceWriter.func1协程不存在。

  问题明确了,从管道中生产日志的子协程因为某些起因退出了。该协程有两处逻辑,在呈现谬误时候,间接return,会导致协程的完结。只惋惜灰度环境没有采集日志,工夫太长日志都不存在了,无奈确定协程退出的真正起因。

  另外,查看日志文件的状态等都是失常的:

//日志门路,权限等失常# ll /home/logs/xeslog/talcamp/talcamp.log-rw-r--r--    1 root     root             0 Nov 10 00:00 /home/logs/xeslog/talcamp/talcamp.log//服务失常关上日志文件# lsof -p 67 | grep "talcamp.log"9       /home/www/talcamp/bin/talcamp   /home/logs/xeslog/talcamp/talcamp.log

非阻塞革新

  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函数,第三个参数标识是否阻塞以后协程)。另外,咱们也能够稍加革新,实现管道带超时工夫的读写。