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. 【计算机网络 12(1),尚学堂马士兵Java视频教程
  2. 【程序猿历程,史上最全的Java面试题集锦在这里
  3. 【程序猿历程(1),Javaweb视频教程百度云
  4. Notes on MySQL 45 lectures (1-7)
  5. [computer network 12 (1), Shang Xuetang Ma soldier java video tutorial
  6. The most complete collection of Java interview questions in history is here
  7. [process of program ape (1), JavaWeb video tutorial, baidu cloud
  8. Notes on MySQL 45 lectures (1-7)
  9. 精进 Spring Boot 03:Spring Boot 的配置文件和配置管理,以及用三种方式读取配置文件
  10. Refined spring boot 03: spring boot configuration files and configuration management, and reading configuration files in three ways
  11. 精进 Spring Boot 03:Spring Boot 的配置文件和配置管理,以及用三种方式读取配置文件
  12. Refined spring boot 03: spring boot configuration files and configuration management, and reading configuration files in three ways
  13. 【递归,Java传智播客笔记
  14. [recursion, Java intelligence podcast notes
  15. [adhere to painting for 386 days] the beginning of spring of 24 solar terms
  16. K8S系列第八篇(Service、EndPoints以及高可用kubeadm部署)
  17. K8s Series Part 8 (service, endpoints and high availability kubeadm deployment)
  18. 【重识 HTML (3),350道Java面试真题分享
  19. 【重识 HTML (2),Java并发编程必会的多线程你竟然还不会
  20. 【重识 HTML (1),二本Java小菜鸟4面字节跳动被秒成渣渣
  21. [re recognize HTML (3) and share 350 real Java interview questions
  22. [re recognize HTML (2). Multithreading is a must for Java Concurrent Programming. How dare you not
  23. [re recognize HTML (1), two Java rookies' 4-sided bytes beat and become slag in seconds
  24. 造轮子系列之RPC 1:如何从零开始开发RPC框架
  25. RPC 1: how to develop RPC framework from scratch
  26. 造轮子系列之RPC 1:如何从零开始开发RPC框架
  27. RPC 1: how to develop RPC framework from scratch
  28. 一次性捋清楚吧,对乱糟糟的,Spring事务扩展机制
  29. 一文彻底弄懂如何选择抽象类还是接口,连续四年百度Java岗必问面试题
  30. Redis常用命令
  31. 一双拖鞋引发的血案,狂神说Java系列笔记
  32. 一、mysql基础安装
  33. 一位程序员的独白:尽管我一生坎坷,Java框架面试基础
  34. Clear it all at once. For the messy, spring transaction extension mechanism
  35. A thorough understanding of how to choose abstract classes or interfaces, baidu Java post must ask interview questions for four consecutive years
  36. Redis common commands
  37. A pair of slippers triggered the murder, crazy God said java series notes
  38. 1、 MySQL basic installation
  39. Monologue of a programmer: despite my ups and downs in my life, Java framework is the foundation of interview
  40. 【大厂面试】三面三问Spring循环依赖,请一定要把这篇看完(建议收藏)
  41. 一线互联网企业中,springboot入门项目
  42. 一篇文带你入门SSM框架Spring开发,帮你快速拿Offer
  43. 【面试资料】Java全集、微服务、大数据、数据结构与算法、机器学习知识最全总结,283页pdf
  44. 【leetcode刷题】24.数组中重复的数字——Java版
  45. 【leetcode刷题】23.对称二叉树——Java版
  46. 【leetcode刷题】22.二叉树的中序遍历——Java版
  47. 【leetcode刷题】21.三数之和——Java版
  48. 【leetcode刷题】20.最长回文子串——Java版
  49. 【leetcode刷题】19.回文链表——Java版
  50. 【leetcode刷题】18.反转链表——Java版
  51. 【leetcode刷题】17.相交链表——Java&python版
  52. 【leetcode刷题】16.环形链表——Java版
  53. 【leetcode刷题】15.汉明距离——Java版
  54. 【leetcode刷题】14.找到所有数组中消失的数字——Java版
  55. 【leetcode刷题】13.比特位计数——Java版
  56. oracle控制用户权限命令
  57. 三年Java开发,继阿里,鲁班二期Java架构师
  58. Oracle必须要启动的服务
  59. 万字长文!深入剖析HashMap,Java基础笔试题大全带答案
  60. 一问Kafka就心慌?我却凭着这份,图灵学院vip课程百度云