在一个略显疲惫但依然坚守的下午,随着在键盘上噼里啪啦地敲下最后一行return Result.ok(“success”),接口搞定,任务完成;眼睛瞥了下右下角时间:18:32,得,伸个懒腰,揉把眼睛,下楼干饭走起!
就在刚起身还没来得及扶下伴我忙碌了一天的镜框,微信头像轻轻跳动,线上项目维护群里,一个运维同事反馈,管理平台上显示主机卫士全离线了,已经有半个多小时了,始终没法重新上线,问题很严重,十万火急。我当时就想,难道是网络不通了,不应该呀,这等基础原因运维也不会找到研发这边呀,秉着始终客户至上原则,当时就叫他都先别操作了,保留现场,协调一个远程环境,立马重新坐下撸起袖子开干!
该现场包含一个工控产品,多个车间部署终端,然后通过管理平台统一管控,其中判断终端是否能被正常管控到(比如网络可达等),采用的是客户端-服务端建立TCP长连接心跳进行通信,服务用的Netty框架。
现场定位
终端离线了,那最直接的原因铁定是心跳处理接口出错了,要不TCP断连了,要不就是处理逻辑报错了,没能重置在线状态。
话不多说,现场问题,跑不了的第一步,查看cpu使用率。
观察了一段时间,cpu基本持续在50%-70%之间,没什么问题。
既然cpu性能上没问题,那就再看一下处理终端上线状态的线程是否还存活以及TCP连接的情况,走的是4575端口。
Jstack 2646319 | grep HeartBeatThread -C 10 命令查看线程情况。
没问题,线程依然存活着。
netstat - ant | grep 4575继续用命令查看下连接数。
瞬间惊呆,一脸的不可思议,现场三千多台终端,也就是三千多个连接,基本上全是CLOSE_WAIT状态了,没有几台正常建连的,而且这些CLOSE_WAIT的连接出现以后不会消失。
第一时间,这不得不让我又开始怀疑起一开始运维同事所反馈的,端到端的网络可达性了。不废话,直接抓包,讲究的就是一个以德服人。
随着抓包结果一出,还真让我的自信心稍微地一颤,这不科学呀,cpu资源没问题,线程也活着,网络也可达,这难道真的要上升到玄学了吗?
不急不急,谁让我们学的专业就是计算机科学与技术呢,先让我们简单地回顾下这TCP三次握手四次挥手收发包的过程。
TCP三次握手四次挥手示意图
我们可以看到,CLOSE_WAIT状态出现在被动关闭方,当收到对端FIN以后回复ACK,但是自身没有发送FIN包之前,所以这里的原因就很清楚了,出现永远存在的CLOSE_WAIT的连接是因为,收到了对端的FIN包,但是自己一直没有回复FIN。
接下来就再次重新看下我们前面抓包的信息,也证实了这点。
那问题就落在了为什么没有回复 FIN,这是一个客户端发起的请求,三次握手成功以后,终端服务会马上发送 FIN,理论上Netty服务也会立刻回复 FIN,但是没有任何反应。
对于使用的Netty来说,它就是一个普通的tcp服务端,无非就这几步:
bind、listen
注册 accept 事件到 epoll
epoll_wait 等待连接到来
连接到来时,调用 accept 接收连接
注册新连接的 EPOLLIN、EPOLLERR、EPOLLHUP 等事件到 epoll
epoll_wait 等待事件发生
如果是没有发送 fin,有几个比较明显的可能原因:
第 2 步没有做,压根没有注册 accept 事件(可以排除,肯定有注册)
第 4 步没有做,连接到来时,netty 「忘了」调用 accept 把连接从内核的全连接队列里取走。这里的「忘」可能是因为逻辑 bug 或者 netty 忙于其他事情没有时间取走,这个待会验证
第 5 步没有做,取走了连接,三次握手真正完成,但是没有注册新连接的后续事件
第 2 个原因可以通过半连接队列、全连接队列的积压来确认。ss 命令可以查看全连接队列的大小和当前等待accept的连接个数。
处于 LISTEN 状态的 socket,Recv-Q 表示当前 socket 的完成三次握手等待用户进程 accept 的连接个数,Send-Q 表示当前 socket 全连接队列能最大容纳的连接数。
对于非 LISTEN 状态的 socket,Recv-Q 表示 receive queue 的字节大小,Send-Q 表示 send queue 的字节大小。
通过 ss 命令确认过 Recv-Q 为 0,全连接队列没有积压。
至此最大的嫌疑在第 3 个原因,netty 确实调用了 accept 取走了连接,但是没有注册此连接的任何事件,导致后面收到了 fin 包以后无动于衷。
为什么netty没有能注册事件?
到这里暂时陷入了僵局,但是有一个跟此次问题强相关的现象浮出了水面,就是业务实例在凌晨1点有个定时任务,一开始就load了大量的数据到内存中,导致堆内存占满,持续进行fullgc。
netty 线程也有打印 oom 异常。
这里的OOM异常上面的一个warning表示很可疑,去netty源码中一搜索,发现出现在org.jboss.netty.channel.socket.nio.NioServerBoss#process方法中。
第80行netty调用accept从全连接队列取走连接,第85行调用registerAcceptedChannel,将当前fd设置为非阻塞同时为新连接fd注册事件,具体的逻辑是在org.jboss.netty.channel.socket.nio.NioWorker.RegisterTask#run中。
从错误日志中可以知道,这个方法确实抛出了java.lang.OutOfMemoryError异常。
因此这里的原因就很清楚了,netty这里的处理确实不健壮,一个try-catch包裹了accept连接和注册事件这两个逻辑,当第80行accept成功,但在85行registerAcceptedChannel内部尝试注册事件时因为线程OOM排除异常时就凉凉了,没有close这个新连接,就导致了后面收到fin以后根本不会回复任何包(epoll里压根没有这个fd的感兴趣事件)。
模拟复现
直接改netty源码加点日志重新模拟运行程序。
这个CLOSE_WAIT就一直存在了直到netty进程退出。再来一次然后断开就又多了一个 CLOSE_WAIT。
而且在现场用tcpdump命令抓包的过程中以及分析log日志,发现存在好些IP客户端在重复发起建连,一秒内达到八九次,根本不符合超时重连机制原则,所以获取对应IP客户端的log日志和源码分析,发现是现场客户端V3R6C01B060等几个老版本,总数量1388台,TCP发起建连的逻辑存在错误,会持续频繁地发起连接请求,所以导致OOM期间 CLOSE_WAIT持续增加。
小 结
到这里的问题就很清楚了,总结就是 netty 的代码不够健壮,一个 try-catch 包裹的逻辑太多,在 OOM throwable 异常处理时,没能成功注册事件也没有 close 已创建的连接,导致连接存在但是没有人监听事件处理。
那又是什么原因导致发生OOM呢?
性能问题定位,当然少不了堆栈的一顿分析。
jmap -dump:format=b,file=4575.hprof 2646319 使用jmap命令,从客户现场环境导出dump文件,使用JProfiler工具直接打开分析。
可以看到这个ConcurrentHashMap其实存储了netty的channel对象,最大规格也就是3000台终端对应了3000条数据而已,但这会儿竟然达到了2.5GB多,绝对不正常,继续往下看,然后就发现了EPollSelectorImpl这个对象实例一直在增加。
没办法,只能继续薅源代码了,其实到这一步,问题的原因越来越清晰了,就待破解这内存异常占用问题了。
可以看到,在io.netty.channel.nio#select方法中,呼之欲出netty的老问题就来了——Selector空轮询BUG。
Netty的解决办法总览
对Selector的select操作周期进行统计,每完成一次空的select操作进行一次计数,若在某个周期内连续发生N次空轮询,则触发了epoll死循环bug。
重建Selector,判断是否是其他线程发起的重建请求,若不是则将原SocketChannel从旧的Selector上去除注册,重新注册到新的Selector上,并将原来的Selector关闭。
Netty解决空轮询的4步骤
第一部分:定时阻塞select(timeMillins)
先定义当前时间currentTimeNanos
接着计算出一个执行最少需要的时间timeoutMillis
定时阻塞select(timeMillins)
每次对selectCnt做++操作
第二部分:有效IO事件处理逻辑
第三部分:超时处理逻辑
如果查询超时,则seletCnt重置为1
第四部分: 解决空轮询 BUG
一旦到达SELECTOR_AUTO_REBUILD_THRESHOLD阈值,就需要重建selector来解决这问题
这个阈值默认是512
重建selector,重新注册channel通道
在家里模拟环境验证,搭建了一套和现场一模一样版本的管理平台服务,终端也是同样各个高低版本分布情况和数量规格上压力测试,观察后发现EPollSelectorImpl对象始终没有增加。
不由得怀疑是由于系统上的某些参数设置不同导致的,因为我们研发平时使用好几套不同厂商不同型号的服务器做测试,以及研发测试环境经常修改参数做功能适配,然后和现场环境对比,发现文件句柄数、服务系统参数等都一致,只是服务器配置不一样,现场的是内存128G/48核的,远比家里的16G/4核的高出不少,问题已经定位到这一步了,所以为了能够排除最后一丝的差异性,又协调过来一台相同配置的服务器,重新部署上管理平台服务上压力。
这次很明显地可以发现这个EPollSelectorImpl对象在不断地增加, 然后结合Netty针对这个空轮询的处理方式,猜想原因可能就是,服务器性能太高了,再加上错误版本的客户端频繁异常发送请求连接,导致这个时间段次次瞬间就命中默认阈值条件,触发了重建selector的条件。
为了最后一次验证这个猜想,我们临时把SELECTOR_AUTO_REBUILD_THRESHOLD这个阈值配置修改为3,也就是在Netty中关闭了该重建selector功能,再次验证,发现cpu消耗了很多,不过EPollSelectorImpl实例不会再异常地增加。
结 论
过量的请求连接,异常导致了对Netty 的Selector空轮询BUG的触发,使其EPollSelectorImpl对象实例异常不断增加,也就是内存增大导致内存泄漏。
问题解决
对现场出问题的客户端进行最新版本的升级;
平台多个微服务使用了多个netty版本进行了整理统一,使用较新的版本;
对服务整体代码进行了梳理,尤其是针对获取tcp心跳报文接口的逻辑处理,包括一些不必要的加锁,阻塞访问数据库逻辑操作等进行了性能优化。
渠道合作咨询 田先生 15611262709
稿件合作 微信:shushu12121
📍发表于:中国 北京