Golang之HTTP服务『假死』问题排查

LNMPRG源码研究

李乐

问题描述

  下午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:xxxx"

//三次握手
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: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
     xxxx//log4go.(*FileLogTraceWriter).LogWrite
     xxxx//log4go.Logger.LogTraceMap
     xxxx//log4go.LogTraceMap
     xxxx//builders.(*TraceBuilder).LoggerX
     xxxx/Logger.Ix
     xxxx//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
    xxxx/log4go.NewFileLogTraceWriter.func2

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

  问题明白了,从管道中消费日志的子协程因为某些原因退出了。该协程有两处逻辑,在出现错误时候,直接return,会导致协程的结束。只可惜灰度环境没有采集日志,时间太长日志都不存在了,无法确定协程退出的真正原因。

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

//日志路径,权限等正常
# ll /xxxx/talcamp.log
-rw-r--r--    1 root     root             0 Nov 10 00:00 /xxxx/talcamp.log

//服务正常打开日志文件
# lsof -p 67 | grep "talcamp.log"
9       /xxxx/bin/talcamp   /xxxx/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函数,第三个参数标识是否阻塞当前协程)。另外,我们也可以稍加改造,实现管道带超时时间的读写。

阅读 3k

一群热爱代码的人 研究Nginx PHP Redis Memcache Beanstalk 等源码 以及一群热爱前端的人

7k 声望
12.6k 粉丝
0 条评论

一群热爱代码的人 研究Nginx PHP Redis Memcache Beanstalk 等源码 以及一群热爱前端的人

7k 声望
12.6k 粉丝
文章目录
宣传栏