Netty性能压测偶现消息发送时延毛刺案例

问题描述

业务使用Netty发送消息，性能压测过程中偶现一些消息发送耗时超过1S，采集了问题发生时CPU使用率，发现CPU占用率并不高，资源不是瓶颈。怀疑是代码BUG，相关性能统计代码如下所示：

        int sendBytes = ((ByteBuf)msg).readableBytes();

        long beginTime = System.currentTimeMillis();

        ChannelFuture writeFuture = ctx.writeAndFlush(msg);

        writeFuture.addListener((f) ->

        {

            long costTime = System.currentTimeMillis() - beginTime;

            if (costTime > 1000)

                logger.warn("Send msg cost time is : " + costTime);

            totalSendBytes.getAndAdd(sendBytes);

        });

问题分析

Netty消息发送耗时大，可能原因如下：

• 发生了导致STW的GC，从现象看问题发生时单个消息发送耗时大于1S，可能是Full GC导致的，需要采集GC日志或者通过内存工具进行分析。除了GC导致的应用暂停，JIT优化、取消偏向锁等也会导致应用暂停。因此建议定位问题时临时加上 -XX:+PrintGCApplicationStoppedTime、-XX:+PrintSafepointStatistics -XX: PrintSafepointStatisticsCount=1来统计其它导致应用暂停的原因

• 业务ChannelHandler的outbound操作发生了条件阻塞，导致Netty的NioEventLoop线程被意外阻塞，无法执行消息发送操作

• 对端消息读取慢，或者一段时间内没有读取消息（例如发生了Full GC），导致发送端tcp缓冲区积压，消息无法发送。通过netstat命令查看Recv-Q和Send-Q状态，可以判断tcp缓冲区是否有消息积压

定位结果

按照上面的思路进行排查，发现业务的ChannelHandler对消息发送做了拦截，在执行拦截逻辑时，依赖某个外部条件，如果检测不满足，则sleep 1S再次检测，直到条件满足，才会继续执行后续ChannelHandler，这导致了Netty的NioEventLoop线程被随机阻塞,表现出来的现象就是偶现的消息发送超过1S。

问题总结

• 无论在任何情况下，业务的ChannelHandler都不能执行诸如sleep、wait、发起同步网络读写、数据库操作、同步读写本地磁盘文件等可能导致NioEventLoop线程被阻塞的操作

• 代码中尽量不要通过while循环 + sleep这种方式来检测条件是否满足，建议采用事件触发或者异步回调的方式，当某个事件触发时，订阅或者注册该事件的监听器可以被唤醒并执行