一次线上有关问题排查的坎坷经历

一次线上问题排查的坎坷经历

问题描述：某生产环境在业务高峰期，偶现服务调用时延突刺问题，时延突然增大的服务没有固定规律，比例虽然很低，但是对客户的体验影响很大，需要尽快定位出问题原因并解决。

问题分析

服务调用时延增大，但并不是异常，因此运行日志并不会打印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也不准确，大家知道为什么吗？这个留作问题，供大家自己思考。