Arthas协助MQ消费性能优化

背景

项目中使用AWS的SQS消息队列进行异步处理，QA通过压测发现单机TPS在23左右，目标性能在500TPS，所以需要对消费逻辑进行优化，提升消费速度。

目标

消费TPS从23提升到500

优化流程

优化的思路是先分析定位性能瓶颈，再针瓶颈进行优化。

性能定位

要定位性能，先要准确评估每秒处理的消费数量，以及处理每个消息过程中，每一步操作的耗时，发现耗时大头在哪里。

准确评估消费速度（TPS）

消费消息的入口是AwsConsumer#doUpdateCoin，所以可以通过Arthas的monitor命令监控方法的执行TPS和RT。

> monitor -c 1 AwsConsumer doUpdateCoin -n 1000

这个命令会统计doUpdateCoin的调用信息，每1秒打印一次结果，总共打印1000次。通过它能定量分析消费的TPS，命令会返回以下信息。

监控项	说明
timestamp	时间戳
class	Java 类
method	方法（构造方法、普通方法）
total	调用次数
success	成功次数
fail	失败次数
rt	平均 RT
fail-rate	失败率

这是一次调用的结果：

可以看到方法每秒执行26次，平均执行时间是179.44秒。从这里我们能得出两个结论：

1. TPS是26，的确不高
2. AVT-RT在179.44ms，那么一个线程TPS约等于5。

因为RT比较高，猜测在RT上还有优化的空间，下面从每条消息消费的过程，继续看是否存在瓶颈。

查看每次处理的明细

要看每次请求的信息，可以通过tt命令，它会采集方法每次执行的耗时、成功还是失败。

> tt -t AwsConsumer doUpdateCoin -n 1000

表格字段	字段解释
INDEX	时间片段记录编号，每一个编号代表着一次调用，后续 tt 还有很多命令都是基于此编号指定记录操作，非常重要。
TIMESTAMP	方法执行的本机时间，记录了这个时间片段所发生的本机时间
COST(ms)	方法执行的耗时
IS-RET	方法是否以正常返回的形式结束
IS-EXP	方法是否以抛异常的形式结束
OBJECT	执行对象的hashCode()，注意，曾经有人误认为是对象在 JVM 中的内存地址，但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体
CLASS	执行的类名
METHOD	执行的方法名

这是一次调用的结果：

从这里可以看出，消息处理耗时有的大，有的小，说明处理性能不稳定。需要再深入看RT较大的消息耗时在哪里。

处理一条消息的内部耗时

要看单次处理过程中，每个步骤的耗时，一般我们会通过在代码前后记录时间，再用日志打印出来。例如：long s = System.currentTimeMillis();

这种方式效率很低，需要不断加日志，并重新部署服务。Arthas有一个trace命令，可以查看方法的调用栈信息，包括调用的方法和方法执行的耗时。

> trace AwsConsumer doUpdateCoin '#cost > 100' -n 1

这是一次调用的结果：

 

这个命令会打印doUpdateCoin耗时大于100ms的请求调用栈信息，可以看到doUpdateCoin方法执行了323ms，其中99.62%的耗时集中在PlayerService:loadByOpenId()方法调用。然后我们就会想看一下loadByOpenId方法到底什么地方耗时。

trace命令不能直接指定调用栈的层级，可以通过动态trace的方式，再创建一个listener去监听loadByOpenId方法，这样会把第二个listener的结果打印在前面的trace结果上。

> trace PlayerService loadByOpenId --listenerId 9

 

可以看到，在原来的结果上多了loadByOpenId方法调用的明细。也发现了loadByOpenId方法耗时集中在load方法上，这是ORM框架提供的方法，直接去查询数据库。所以基本可以断定，本次处理慢是由于这个查询引起的。后面就是看查询条件是没有命中索引导致了慢，还是数据库本身性能存在问题。

总结

因为本次压测是在测试数据库，所以数据库本身不稳定，虽然定位到了这个性能瓶颈，对消费逻辑优化帮助不大，需要更精准的评估线上数据库的性能。但是通过monitor命令长时间观察doUpdateCoin方法的执行情况，发现大部分时间平均RT其实是比较低的，所以不应该是单次请求慢而降低了总体的消费TPS。可能是因为SQS消息拉取阶段存在瓶颈，所以尝试加大了消费的线程数、将单条拉取改成批量拉取。重新压测后，消费TPS从23提升到了342。