一、背景描述#
基于Netty做了一个消息推送服务，将消息总线中的消息推送给与消息推送服务器进行socket连接的client。
推送服务描述
二、问题描述#
进行压力测试，当消息发送速率达到5w条/秒时：
1、 JVM进程出现频繁FullGC，且每次FullGC并不能回收年老代堆内存空间；
2、 top命令查看服务器资源使用情况，服务器内存被打满；
3、负责FullGC的线程不断循环执行导致CPU100%；
三、问题排查#
1、查询占用CPU较多线程的堆栈信息####
排查步骤
- 1）jps或ps命令获取jvm进程的pid；
- 2）top -H p pid查询jvm进程中各个线程占用的系统资源；
- 3）jstack pid获取jvm进程的堆栈信息->stack.txt；
- 4）将占用CPU资源较多线程的tid转换为十六进制，从堆栈信息文件stack.txt中匹配对应堆栈信息；
截取几个堆栈信息如下
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:622)
at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
- locked <0x0000000080d00f38> (a java.lang.Object)
at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:270)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:688)
at io.netty.channel.ChannelOutboundBuffer$Entry.newInstance(ChannelOutboundBuffer.java:693)
at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:658)
at io.netty.handler.stream.ChunkedWriteHandler.doFlush(ChunkedWriteHandler.java:304)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:688)
at sun.misc.Unsafe.freeMemory(Native Method)
at java.nio.DirectByteBuffer$Deallocator.run(DirectByteBuffer.java:94)
at io.netty.util.internal.Cleaner0.freeDirectBuffer(Cleaner0.java:66)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:688)
分析堆栈信息，基本是Netty的IO线程进行select、write、flush和freeDirectBuffer的操作。
2、jvm堆内存使用分析####
jstat -gcutil pid 1s 命令，查询JVM进程GC情况，发现Full GC短期大量执行，且无法回收年老代内存空间。
jmap -histo pid > histo.txt命令，打印JVM进程中每个class的实例数目,内存占用,类全名信息，如下：
- 正常情况刚Yong GC完时的内存占用
1: 457482 35,387,296 [C
2: 16678 13,773,280 [I
3: 63772 9,237,488 [B
4: 122,459 7,837,376 java.nio.DirectByteBuffer
5: 53,091 7,193,480 [Ljava.lang.Object;
6: 90076 6485472 io.netty.channel.DefaultChannelHandlerContext
7: 59706 4298832 io.netty.buffer.UnpooledUnsafeDirectByteBuf
8: 122777 3928864 java.util.HashMap$Node
9: 120320 2887680 java.lang.String
10: 43714 2447984 io.netty.buffer.UnpooledHeapByteBuf
Total 2360002 138,412,016
- 正常情况发生Yong GC前的内存占用
1: 5800859 438,101,408 [C
2: 717064 105,584,984 [B
3: 1375972 88,062,208 java.nio.DirectByteBuffer
4: 675654 48,647,088 io.netty.buffer.UnpooledUnsafeDirectByteBuf
5: 1526018 36,624,432 java.lang.String
6: 621771 34,819,176 io.netty.buffer.UnpooledHeapByteBuf
7: 620271 34,735,176 java.nio.StringCharBuffer
8: 621910 29,851,680 io.netty.channel.DefaultChannelPromise
9: 621523 29833104 java.nio.HeapByteBuffer
10: 1235512 29652288 java.lang.StringBuilder
Total 19200129 1,093,142,504
- 不断进行Full GC时的内存占用
1: 14,315,627 687,150,096 io.netty.channel.DefaultChannelPromise
2: 14,314,546 572,581,840 io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask
3: 14,314,631 458,068,192 io.netty.util.Recycler$DefaultHandle
4: 14,061,517 337,476,408 com.youzan.platform.ordermsgpush.server.handler.MacdonaldMessageHandler$$Lambda$34/1592197748
5: 339988 11723152 [C
6: 443875 10653000 com.youzan.platform.ordermsgpush.server.common.CommandOut
7: 339909 8157816 java.lang.String
8: 252671 6064104 com.youzan.platform.ordermsgpush.server.common.CommandIn
9: 252451 6058824 com.youzan.platform.ordermsgpush.server.dispatcher.network.NetWorkEventDispatcher$1
10: 252451 6058824 com.youzan.platform.ordermsgpush.server.dispatcher.network.
Total 59789703 2,146,390,000
分析结论：
- Netty使用DirectByteBuffer缓存待发送的数据，正常情况下，会存在DirectByteBuffer对象，实际内存空间在堆外申请；
- 不断发生Full GC异常时，JVM堆内存被大量的DefaultChannelPromise、WriteAndFlushTask、Recycler对象填满，可见是因为writeAndFlush任务的产生速度大大超过socket连接的TCP发送缓冲区消化速度，导致Netty不断申请堆外内存在应用层缓存待发送的数据，最终耗尽系统内存资源；
3、产生问题的代码####
发送数据的代码片段如下：
channelHandlerContext.writeAndFlush(commandOut).addListener(future -> {
if (!future.isSuccess()) {
logger.warn("unexpected push. msg:{} fail:{}", msg, future.cause().getMessage());
}
});
由于ChannelHandlerContext.writeAndFlush()只是产生write任务和flush任务，交由Netty的IO线程处理，其ChannelFuture返回时并不保证flush任务已执行完毕并将数据写入到了连接对应的TCP发送缓冲区。
如果不对writeAndFlush()的调用速率进行限制，当应用对socket进行写操作的速率超过socket实际发送速率时，对应连接的TCP发送缓冲区会被填满，后续写操作的待发送数据会由Netty不断申请内存缓存，最终导致内存溢出。
解决方法：
if(channelHandlerContext.channel().isWritable()){
channelHandlerContext.writeAndFlush(commandOut).addListener(future -> {
if (!future.isSuccess()) {
logger.warn("unexpected push. msg:{} fail:{}", msg, future.cause().getMessage());
}
});
}else{
try {
channelHandlerContext.writeAndFlush(commandOut).sync();
logger.info("publish macdonaldMsg,sended. remoteAddress:[{}], msg:[{}]", channelHandlerContext.channel().remoteAddress(), msg);
} catch (InterruptedException e) {
logger.info("write and flush msg exception. msg:[{}]",msg,e);
}
}
调用writeAndFlush()方法前先判断当前Channel的可写入状态，若状态为可写入说明待发送数据量并未堆积超限，可以进行异步发送；否则需要执行sync()方法等待发送数据真正成功写入socket的TCP发送缓冲区，然后在执行下一次的write操作，防止write速率过快导致内存溢出。
