一次线上问题排查的坎坷经历
一次线上问题排查的坎坷经历
一次线上问题排查的坎坷经历
问题描述：某生产环境在业务高峰期，偶现服务调用时延突刺问题，时延突然增大的服务没有固定规律，比例虽然很低，但是对客户的体验影响很大，需要尽快定位出问题原因并解决。
问题分析
服务调用时延增大，但并不是异常，因此运行日志并不会打印ERROR日志，单靠传统的日志无法进行有效问题定位。利用分布式消息跟踪系统，进行分布式环境的故障定界。
通过对服务调用时延进行排序和过滤，找出时延增大的服务调用链详细信息，发现业务服务端处理很快，但是消费者统计数据却显示服务端处理非常慢，调用链两端看到的数据不一致，怎么回事？
对调用链的埋点日志进行分析发现，服务端打印的时延是业务服务接口调用的时延，并没有包含：
-
通信端读取数据报、消息解码和内部消息投递、队列排队的时间；
-
通信端编码业务消息、在通信线程队列排队时间、消息发送到Socket的时间。
调用链的工作原理图
调用链埋点日志改进
优化调用链埋点日志，措施如下：
-
包含客户端和服务端消息编码和解码的耗时
-
包含请求和应答消息在业务线程池队列中的排队时间；
-
包含请求和应答消息在通信线程发送队列（数组）中的排队时间
同时，为了方便问题定位，我们需要打印输出Netty的性能统计日志，主要包括：
-
每条链路接收的总字节数、周期T接收的字节数、消息接收CAPs;
-
每条链路发送的总字节数、周期T发送的字节数、消息发送CAPs;
优化之后，上线运行一天之后，我们通过分析比对Netty性能统计日志、调用链日志，发现双方的数据并不一致，Netty性能统计日志统计到的数据与前端门户看到的也不一致，因为怀疑是新增的性能统计功能存在BUG，继续问题定位。
性能统计功能问题定位
首先对消息发送功能进行CodeReview，发现代码调用完writeAndFlush之后直接对发送的请求消息字节数进行计数，代码如下：
消息发送性能统计问题总结
通过对writeAndFlush方法展开分析，我们发现性能统计代码存在如下几个问题：
-
业务ChannelHandler的执行时间
-
ByteBuf在ChannelOutboundBuffer 数组中排队时间
-
NioEventLoop线程调度时间，它不仅仅只处理消息发送，还负责数据报读取、定时任务执行以及业务定制的其它I/O任务
-
JDK NIO类库将ByteBuffer写入到网络的时间，包括单条消息的多次写半包
由于性能统计遗漏了上述4个步骤的执行时间，因此统计出来的性能比实际值更高，这会干扰我们的问题定位。
其它常见性能统计误区汇总
1、调用write 方法之后就开始统计发送速率，示例代码如下：
2、消息编码时进行性能统计，示例代码如下：
编码之后，获取out可读的字节数，然后做累加。编码完成，ByteBuf并没有被加入到发送队列（数组）中，因此在此时做性能统计仍然是不准的。
正确的做法
1、调用writeAndFlush方法之后获取ChannelFuture；
2、新增消息发送ChannelFutureListener，监听消息发送结果，如果消息写入网络Socket成功，则Netty会回调ChannelFutureListener的operationComplete方法；
3、在消息发送ChannelFutureListener的operationComplete方法中进行性能统计。
示例代码如下：
问题定位出来之后，按照正确的做法对Netty性能统计代码进行了修正，上线之后，结合调用链日志，很快定位出了业务高峰期偶现的部分服务时延毛刺较大问题，优化业务线程池参数配置之后问题得到解决。
留给读者的思考
除了消息发送性能统计之外，Netty数据报的读取、消息接收CAPs性能统计也非常容易出错，我们第一版性能统计代码消息接收CAPs也不准确，大家知道为什么吗？这个留作问题，供大家自己思考。