最近经常发生thrift服务半夜宕机的问题,虽然是测试环境,但是每天早上重启也很恶心。
经过很长时间的摸索,终于找到了原因。先说背景:
我们用的thrift版本是0.9.2,用做service的rpc框架,某一天开始,早上到公司发现测试环境的很多服务挂掉了,一头雾水,看内存监控,发现半夜的时候,很多服务的内存涨了一倍不止,发生了堆内存溢出(java.lang.OutOfMemoryError: Java heap space),报错如下:
2023-01-04 01:03:21.294 [Thread-5] ERROR o.a.t.server.TThreadedSelectorServer [TThreadedSelectorServer.java : 553] - run() exiting due to uncaught error
java.lang.OutOfMemoryError: Java heap spaceat java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57) ~[na:1.8.0_212]at java.nio.ByteBuffer.allocate(ByteBuffer.java:335) ~[na:1.8.0_212]at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.read(AbstractNonblockingServer.java:371) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.AbstractNonblockingServer$AbstractSelectThread.handleRead(AbstractNonblockingServer.java:203) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.TThreadedSelectorServer$SelectorThread.select(TThreadedSelectorServer.java:590) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.TThreadedSelectorServer$SelectorThread.run(TThreadedSelectorServer.java:545) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]
刚开始没有往thrift身上想,毕竟一个优秀的rpc框架,facebook出品
首先,排查思路就来到了导出内存快照,看对象的,结果,导出来的hprof文件才几百兆,远远小于内存占用的几个G,看不出有什么问题。
然后,堆内没问题,那看看堆外。加了-XX:NativeMemoryTracking=detail参数(线上环境慎用),去掉了-XX:+DisableExplicitGC,然后使用
jcmd pid VM.native_memory命令查看,发现Internal区域占用了很大空间。
一番学习(百度,谷歌)之后,这是块堆外空间,紧接着又上参数了,配置了直接内存大小限制 -XX:MaxDirectMemorySize=xM。半夜再次发生OOM,不同的是,这次是直接内存溢出(java.lang.OutOfMemoryError: Direct buffer memory),看报错发现是thrift读取请求申请直接内存导致的,报错如下:
2023-01-04 01:03:21.799 [Thread-4] ERROR o.a.t.server.TThreadedSelectorServer [TThreadedSelectorServer.java : 553] - run() exiting due to uncaught error
java.lang.OutOfMemoryError: Direct buffer memoryat java.nio.Bits.reserveMemory(Bits.java:694) ~[na:1.8.0_212]at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123) ~[na:1.8.0_212]at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311) ~[na:1.8.0_212]at sun.nio.ch.Util.getTemporaryDirectBuffer(Util.java:241) ~[na:1.8.0_212]at sun.nio.ch.IOUtil.read(IOUtil.java:195) ~[na:1.8.0_212]at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) ~[na:1.8.0_212]at org.apache.thrift.transport.TNonblockingSocket.read(TNonblockingSocket.java:142) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.internalRead(AbstractNonblockingServer.java:539) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.read(AbstractNonblockingServer.java:388) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.AbstractNonblockingServer$AbstractSelectThread.handleRead(AbstractNonblockingServer.java:203) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.TThreadedSelectorServer$SelectorThread.select(TThreadedSelectorServer.java:590) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]at org.apache.thrift.server.TThreadedSelectorServer$SelectorThread.run(TThreadedSelectorServer.java:545) ~[user_service_runnable.20230103204205.981d7a5da67f15db41243178083f5842e278631d:na]
终于把目光移到了thrift身上(一开始没有怀疑它),于是去搜索了thrift 内存溢出,真相大白,原来是http方式调用导致的。这篇写的不错,跟我们出现的现象一样:
https://blog.csdn.net/xmtblog/article/details/79431748?utm_source=blogxgwz8
原来http方式请求thrift服务的时候,会反序列化失败,默认读取 接收数据的前四个字节作为frameSize。因为http请求是不规范的,前四个字节一算,要申请几百M甚至1G以上,一下就搞炸了。
用http方式试了下,http://127.0.0.1:port/123, 果然OOM了。
thrift是有一个参数maxReadBufferBytes,可以控制frameSize最大值的,超过报错,好死不死,我们用的0.9.2版本,这个参数默认是Long的最大值,高达很多T,在0.12.0版本后已经修改为256M了。thrift读取数据的read方法截图如下:
源码如下:
于是在我们框架TThreadedSelectorServer 构造方法中加了maxReadBufferBytes = 1024 * 1024,限制1M大小。
发SNAPSHOT包,重启,再次用http方式试了下,http://127.0.0.1:port/123,没有发生OOM,发生如下报错,与上面截图里第二个红箭头对上了:
2023-01-06 02:25:06.827 [Thread-6] ERROR o.a.t.s.AbstractNonblockingServer$FrameBuffer
[AbstractNonblockingServer.java : 356] - Read a frame size of 369295360, which is bigger than the maximum allowable buffer size for ALL connections.
至此,问题解决。
为啥会有http请求调我们这个port呢,不得而知,因为我们方便在本机debug,测试环境一些端口防火墙是放开的,一着不慎就招贼了。
其实这个问题,相信也有大佬第一次看到报错,就能正确分析,去找thrift的原因了。我还是能力不足,排查了很久,但是
Talk is cheap, just do it!