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

LNMPR源码研究 2020-11-10 14:21:45
http 服务 golang 问题 假死


问题描述

下午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 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
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函数,第三个参数标识是否阻塞当前协程)。另外,我们也可以稍加改造,实现管道带超时时间的读写。

版权声明
本文为[LNMPR源码研究]所创,转载请带上原文链接,感谢
https://segmentfault.com/a/1190000037785685

  1. [front end -- JavaScript] knowledge point (IV) -- memory leakage in the project (I)
  2. This mechanism in JS
  3. Vue 3.0 source code learning 1 --- rendering process of components
  4. Learning the realization of canvas and simple drawing
  5. gin里获取http请求过来的参数
  6. vue3的新特性
  7. Get the parameters from HTTP request in gin
  8. New features of vue3
  9. vue-cli 引入腾讯地图(最新 api,rocketmq原理面试
  10. Vue 学习笔记(3,免费Java高级工程师学习资源
  11. Vue 学习笔记(2,Java编程视频教程
  12. Vue cli introduces Tencent maps (the latest API, rocketmq)
  13. Vue learning notes (3, free Java senior engineer learning resources)
  14. Vue learning notes (2, Java programming video tutorial)
  15. 【Vue】—props属性
  16. 【Vue】—创建组件
  17. [Vue] - props attribute
  18. [Vue] - create component
  19. 浅谈vue响应式原理及发布订阅模式和观察者模式
  20. On Vue responsive principle, publish subscribe mode and observer mode
  21. 浅谈vue响应式原理及发布订阅模式和观察者模式
  22. On Vue responsive principle, publish subscribe mode and observer mode
  23. Xiaobai can understand it. It only takes 4 steps to solve the problem of Vue keep alive cache component
  24. Publish, subscribe and observer of design patterns
  25. Summary of common content added in ES6 + (II)
  26. No.8 Vue element admin learning (III) vuex learning and login method analysis
  27. Write a mini webpack project construction tool
  28. Shopping cart (front-end static page preparation)
  29. Introduction to the fluent platform
  30. Webpack5 cache
  31. The difference between drop-down box select option and datalist
  32. CSS review (III)
  33. Node.js学习笔记【七】
  34. Node.js learning notes [VII]
  35. Vue Router根据后台数据加载不同的组件(思考-&gt;实现-&gt;不止于实现)
  36. Vue router loads different components according to background data (thinking - & gt; Implementation - & gt; (more than implementation)
  37. 【JQuery框架,Java编程教程视频下载
  38. [jQuery framework, Java programming tutorial video download
  39. Vue Router根据后台数据加载不同的组件(思考-&gt;实现-&gt;不止于实现)
  40. Vue router loads different components according to background data (thinking - & gt; Implementation - & gt; (more than implementation)
  41. 【Vue,阿里P8大佬亲自教你
  42. 【Vue基础知识总结 5,字节跳动算法工程师面试经验
  43. [Vue, Ali P8 teaches you personally
  44. [Vue basic knowledge summary 5. Interview experience of byte beating Algorithm Engineer
  45. 【问题记录】- 谷歌浏览器 Html生成PDF
  46. [problem record] - PDF generated by Google browser HTML
  47. 【问题记录】- 谷歌浏览器 Html生成PDF
  48. [problem record] - PDF generated by Google browser HTML
  49. 【JavaScript】查漏补缺 —数组中reduce()方法
  50. [JavaScript] leak checking and defect filling - reduce() method in array
  51. 【重识 HTML (3),350道Java面试真题分享
  52. 【重识 HTML (2),Java并发编程必会的多线程你竟然还不会
  53. 【重识 HTML (1),二本Java小菜鸟4面字节跳动被秒成渣渣
  54. [re recognize HTML (3) and share 350 real Java interview questions
  55. [re recognize HTML (2). Multithreading is a must for Java Concurrent Programming. How dare you not
  56. [re recognize HTML (1), two Java rookies' 4-sided bytes beat and become slag in seconds
  57. 【重识 HTML ,nginx面试题阿里
  58. 【重识 HTML (4),ELK原来这么简单
  59. [re recognize HTML, nginx interview questions]
  60. [re recognize HTML (4). Elk is so simple