背景
项目中使用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秒。从这里我们能得出两个结论：
- TPS是26，的确不高
- 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。
