如何从时延毛刺问题定位到Netty的性能统计设计
如何从时延毛刺问题定位到Netty的性能统计设计
小编给大家分享一下如何从时延毛刺问题定位到Netty的性能统计设计，相信大部分人都还不怎么了解，因此分享这篇文章给大家参考一下，希望大家阅读完这篇文章后大有收获，下面让我们一起去了解一下吧！
一、背景：
通常情况下，用户以黑盒的方式使用Netty，通过Netty完成协议消息的读取和发送，以及编解码操作，不需要关注Netty的底层实现细节。
在高并发场景下，往往需要统计系统的关键性能KPI数据，结合日志、告警等对故障进行定位分析，如果对Netty的底层实现细节不了解，获取哪些关键性能数据，以及数据正确的获取方式都将成为难点。错误或者不准确的数据可能误导定位思路和方向，导致问题迟迟不能得到正确解决。
二、时延毛刺故障排查的艰辛历程:
问题现象：某电商生产环境在业务高峰期，偶现服务调用时延突刺问题，时延突然增大的服务没有固定规律，问题发生的比例虽然很低，但是对客户的体验影响很大，需要尽快定位出问题原因并解决。
时延毛刺问题初步分析：
服务调用时延增大，但并不是异常，因此运行日志并不会打印ERROR日志，单靠传统的日志无法进行有效问题定位。利用分布式消息跟踪系统，进行分布式环境的故障定界。
通过对服务调用时延进行排序和过滤，找出时延增大的服务调用链详细信息，发现业务服务端处理很快，但是消费者统计数据却显示服务端处理非常慢，调用链两端看到的数据不一致，怎么回事？
对调用链的详情进行分析发现，服务端打印的时延是业务服务接口调用的耗时，并没有包含：
（1）服务端读取请求消息、对消息做解码，以及内部消息投递、在线程池消息队列排队等待的时间。
（2）响应消息编码时间、消息队列发送排队时间以及消息写入到Socket发送缓冲区的时间。
服务调用链的工作原理如下：
图1 服务调用链工作原理
将调用链中的消息调用过程详细展开，以服务端读取请求和发送响应消息为例进行说明，如下图所示：
图2 服务端调用链详情
对于服务端的处理耗时，除了业务服务自身调用的耗时之外，还应该包含服务框架的处理时间，具体如下：
（1）请求消息的解码（反序列化）时间。
（2）请求消息在业务线程池中排队等待执行时间。
（3）响应消息编码（序列化）时间。
（4）响应消息ByteBuf在发送队列的排队时间。
由于服务端调用链只采集了业务服务接口的调用耗时，没有包含服务框架本身的调度和处理时间，导致无法对故障进行定界：服务端没有统计服务框架的处理时间，因此不排除问题出在消息发送队列或者业务线程池队列积压而导致时延变大。
服务调用链改进：
对服务调用链埋点进行优化，具体措施如下：
（1）包含客户端和服务端消息编码和解码的耗时。
（2）包含请求和应答消息在队列中的排队时间。
（3）包含应答消息在通信线程发送队列（数组）中的排队时间。
同时，为了方便问题定位，增加打印输出Netty的性能统计日志，主要包括：
（1）当前系统的总链路数、以及每个链路的状态。
（2）每条链路接收的总字节数、周期T接收的字节数、消息接收吞吐量。
（3）每条链路发送的总字节数、周期T发送的字节数、消息发送吞吐量。
对服务调用链优化之后，上线运行一段时间，通过分析比对Netty性能统计日志、调用链日志，发现双方的数据并不一致，Netty性能统计日志统计到的数据与前端门户看到的也不一致，因此怀疑是新增的性能统计功能存在BUG，需要继续对问题进行定位。
都是同步思维惹的祸:
传统的同步服务调用，发起服务调用之后，业务线程阻塞，等待响应，接收到响应之后，业务线程继续执行，对发送的消息进行累加，获取性能KPI数据。
使用Netty之后，所有的网络I/O操作都是异步执行的，即调用Channel的write方法，并不代表消息真正发送到TCP缓冲区中，如果在调用write方法之后就对发送的字节数做计数，统计结果就不准确。
对消息发送功能进行code review，发现代码调用完writeAndFlush方法之后直接对发送的请求消息字节数进行计数，代码示例如下：
public void channelRead(ChannelHandlerContextctx, Object msg) {
int sendBytes =((ByteBuf)msg).readableBytes();
ctx.writeAndFlush(msg);
totalSendBytes.getAndAdd(sendBytes);
}
调用writeAndFlush并不代表消息已经发送到网络上，它仅仅是个异步的消息发送操作而已，调用writeAndFlush之后，Netty会执行一系列操作，最终将消息发送到网络上，相关流程如下所示：
图3 writeAndFlush处理流程图
通过对writeAndFlush方法深入分析，我们发现性能统计代码忽略了如下几个耗时：
（1）业务ChannelHandler的执行时间。
（2）被异步封装的WriteTask/WriteAndFlushTask在NioEventLoop任务队列中的排队时间。
（3）ByteBuf在ChannelOutboundBuffer队列中排队时间。
（4）JDK NIO类库将ByteBuffer写入到网络的时间。
由于性能统计遗漏了上述4个关键步骤的执行时间，因此统计出来的发送速率比实际值会更高一些，这将干扰我们的问题定位思路。
正确的消息发送速率性能统计策略:
正确的消息发送速率性能统计方法如下：
（1）调用writeAndFlush方法之后获取ChannelFuture。
（2）新增消息发送ChannelFutureListener并注册到ChannelFuture中，监听消息发送结果，如果消息写入SocketChannel成功，则Netty会回调ChannelFutureListener的operationComplete方法。
（3）在消息发送ChannelFutureListener的operationComplete方法中进行性能统计。
正确的性能统计代码示例如下：
public voidchannelRead(ChannelHandlerContext ctx, Object msg) {
int sendBytes =((ByteBuf)msg).readableBytes();
ChannelFuture writeFuture =ctx.write(msg);
writeFuture.addListener((f) ->
{
totalSendBytes.getAndAdd(sendBytes);
});
ctx.flush();
}
对Netty消息发送相关源码进行分析，当发送的字节数大于0时，进行ByteBuf的清理工作，代码如下：
protected voiddoWrite(ChannelOutboundBuffer in) throws Exception {
//代码省略...
if (localWrittenBytes <= 0) {
incompleteWrite(true);
return;
}
adjustMaxBytesPerGatheringWrite(attemptedBytes, localWrittenBytes,maxBytesPerGatheringWrite);
in.removeBytes(localWrittenBytes);
--writeSpinCount;
break;
//代码省略...
}
接着分析ChannelOutboundBuffer的removeBytes(long writtenBytes)方法，将发送的字节数与当前ByteBuf可读的字节数进行对比，判断当前的ByteBuf是否完成发送，如果完成则调用remove()清理它，否则只更新下发送进度，相关代码如下：
protected voiddoWrite(ChannelOutboundBuffer in) throws Exception {
//代码省略...
if (readableBytes <=writtenBytes) {
if (writtenBytes != 0) {
progress(readableBytes);
writtenBytes -=readableBytes;
}
remove();
} else {
if (writtenBytes != 0) {
buf.readerIndex(readerIndex+ (int) writtenBytes);
progress(writtenBytes);
}
break;
}
//代码省略...
}
当调用remove()方法时，最终会调用消息发送ChannelPromise的trySuccess方法，通知监听Listener消息已经完成发送，相关代码如下所示：
public booleantrySuccess(V result) {
//代码省略...
if (setSuccess0(result)) {
notifyListeners();
return true;
}
return false;
}
//代码省略...
}
经过以上分析可以看出，调用write/writeAndFlush方法本身并不代表消息已经发送完成，只有监听write/writeAndFlush的操作结果，在异步回调监听中计数，结果才更精确。
需要注意的是，异步回调通知由Netty的NioEventLoop线程执行，即便异步回调代码写在业务线程中，也是由Netty的I/O线程来执行累加计数的，因此这块儿需要考虑多线程并发安全问题，调用堆栈示例如下：
图4 消息发送结果异步回调通知执行线程
如果消息报文比较大，或者一次批量发送的消息比较多，可能会出现“写半包”问题，即一个消息无法在一次write操作中全部完成发送，可能只发送了一半，针对此类场景，可以创建GenericProgressiveFutureListener用于实时监听消息发送进度，做更精准的统计，相关代码如下所示：
privatestatic void notifyProgressiveListeners0(
ProgressiveFuture<?> future,GenericProgressiveFutureListener<?>[] listeners, long progress,long total) {
for(GenericProgressiveFutureListener<?> l: listeners) {
if (l == null) {
break;
}
notifyProgressiveListener0(future,l, progress, total);
}
}
问题定位出来之后，按照正确的做法对Netty性能统计代码进行了修正，上线之后，结合调用链日志，很快定位出了业务高峰期偶现的部分服务时延毛刺较大问题，优化业务线程池参数配置之后问题得到解决。
常见的消息发送性能统计误区:
在实际业务中比较常见的性能统计误区如下：
（1）调用write/ writeAndFlush方法之后就开始统计发送速率。
（2）消息编码时进行性能统计：编码之后，获取out可读的字节数，然后做累加。编码完成并不代表消息被写入到SocketChannel中，因此性能统计也不准确。
Netty关键性能指标采集:
除了消息发送速率，还有其它一些重要的指标需要采集和监控，无论是在调用链详情中展示，还是统一由运维采集、汇总和展示，这些性能指标对于故障的定界和定位帮助都很大。
Netty I/O线程池性能指标:
Netty I/O线程池除了负责网络I/O消息的读写，还需要同时处理普通任务和定时任务，因此消息队列积压的任务个数是衡量Netty I/O线程池工作负载的重要指标。由于Netty NIO线程池采用的是一个线程池/组包含多个单线程线程池的机制，因此不需要像原生的JDK线程池那样统计工作线程数、最大线程数等。相关代码如下所示：
publicvoid channelActive(ChannelHandlerContext ctx) throws Exception {
kpiExecutorService.scheduleAtFixedRate(()->
{
Iterator<EventExecutor>executorGroups = ctx.executor().parent().iterator();
while (executorGroups.hasNext())
{
SingleThreadEventExecutorexecutor = (SingleThreadEventExecutor)executorGroups.next();
int size = executor.pendingTasks();
if (executor == ctx.executor())
System.out.println(ctx.channel() + "--> " + executor +" pending size in queue is : --> " + size);
else
System.out.println(executor+ " pending size in queue is : --> " + size);
}
},0,1000, TimeUnit.MILLISECONDS);
}
}
运行结果如下所示：
图5Netty I/O线程池性能统计KPI数据
Netty发送队列积压消息数：
Netty消息发送队列积压数可以反映网络速度、通信对端的读取速度、以及自身的发送速度等，因此对于服务调用时延的精细化分析对于问题定位非常有帮助，它的采集方式代码示例如下：
publicvoid channelActive(ChannelHandlerContext ctx) throws Exception {
writeQueKpiExecutorService.scheduleAtFixedRate(()->
{
long pendingSize =((NioSocketChannel)ctx.channel()).unsafe().outboundBuffer().totalPendingWriteBytes();
System.out.println(ctx.channel() +"--> " + " ChannelOutboundBuffer's totalPendingWriteBytes is: "
+ pendingSize + "bytes");
},0,1000, TimeUnit.MILLISECONDS);
}
执行结果如下：
图6Netty Channel对应的消息发送队列性能KPI数据
由于totalPendingSize是volatile的，因此统计线程即便不是Netty的I/O线程，也能够正确的读取其最新值。
Netty消息读取速率性能统计:
针对某个Channel的消息读取速率性能统计，可以在解码ChannelHandler之前添加一个性能统计ChannelHandler，用来对读取速率进行计数，相关代码示例如下(ServiceTraceProfileServerHandler类)：
public voidchannelActive(ChannelHandlerContext ctx) throws Exception {
kpiExecutorService.scheduleAtFixedRate(()->
{
int readRates =totalReadBytes.getAndSet(0);
System.out.println(ctx.channel() +"--> read rates " + readRates);
},0,1000, TimeUnit.MILLISECONDS);
ctx.fireChannelActive();
}
public void channelRead(ChannelHandlerContextctx, Object msg) {
int readableBytes =((ByteBuf)msg).readableBytes();
totalReadBytes.getAndAdd(readableBytes);
ctx.fireChannelRead(msg);
}
运行结果如下所示：
图7 NettyChannel 消息读取速率性能统计
以上是“如何从时延毛刺问题定位到Netty的性能统计设计”这篇文章的所有内容，感谢各位的阅读！相信大家都有了一定的了解，希望分享的内容对大家有所帮助，如果还想学习更多知识，欢迎关注恰卡编程网行业资讯频道！
