一个接口的性能问题定位和分析过程
一个接口的性能问题定位和分析过程
通过性能测试平台的介绍和一些培训,我们已经可以进行性能测试了,但是性能测试了除了测试执行之外,性能问题定位和分析也是至关重要的一个环节,下面我们以一个典型的例子,开始一个接口的性能问题定位和分析过程。
接口最初的性能
·TPS:9.6
·MRT:2067ms
·RT90 值:2537ms
·应用服务器 CPU 使用率:30%
我们期望接口的性能TPS 大于150,平均响应时间小于300ms,该接口显然不满足预期。该接口的特点是:响应时间过长,TPS 上不去,并且应用服务器的资源使用未有瓶颈点,那么瓶颈点可能在其他服务器上。出于经验,我们可以想到可能是sql 语句没索引导致的,那么通过Oracle 自带的AWR 工具来验证下,是不是sql 语句的问题。
第一次性能问题定位和分析
AWR 是Oracle 自带的性能统计工具,可以在性能测试开始之前和结束之后分别创建一次快照,然后统计该时间段内的数据库性能情况。AWR 工具会生成HTML 格式的报告,该报告包含非常丰富的统计信息,包含资源使用情况、sql 执行情况、内存使用情况等,我们只需要关注sql 的执行时间就可以发现问题,如下图:
从标红中我们可以看到这条sql 的执行时间接近1s,对于单条sql 的执行时间来说,简单的sql 执行时间应该小于10ms,略微复杂的sql 我们也期望其执行时间可以小于100ms。基于这个标准,我们可以认为该sql 语句确实存在问题。遇到这种慢查询sql,可以首先排查索引原因,去数据库中查看对应表的索引字段,确实是索引未建的问题。
找到问题,我们增加索引后,性能变为:
·TPS:71
·MRT:768ms
·RT90 值:946ms
·应用服务器 CPU 使用率:90% 以上
该性能结果依然没有达到我们的期望值,且从结果看来,问题应该在应用服务这一层。
第二次性能问题定位和分析
遇到CPU 使用率高,且TPS 比较低的情况,我们可以通过jstack 查看内存堆栈信息,排查下比较耗费CPU 的接口、是否存在锁等待等问题。
通过这两部分数据,我们可以看到存在Java IO 的锁竞争,进一步通过堆栈信息,可以找到应用层代码去排查问题原因。
这个问题的原因是在高频调用的一个接口中存在System.out.println 的日志输出。而System.out 的输出是同步输出接口,当有大量的这种类型的输出时,一定会出现锁等待现象。
去掉这种类型的输出语句后:
·TPS:81
·MRT:594ms
·RT90 值:696ms
·应用服务器 CPU 使用率:90% 以上
优化之后的性能依然没有达到我们的要求。
第三次性能问题定位和分析
目前这个接口的问题依然是CPU 使用率高,且TPS 上不去。我们使用JProfiler 工具更进一步的分析消耗CPU 的接口是哪些。
通过JProfiler 的CPU profiler 功能,我们定位到消耗CPU 高的方法为checkLoginIn(),该接口的功能是判断用户是否登录,应该是个比较简单且常用的接口。把这个问题抛给开发后,通过接口的调用信息,开发定位到原因是在请求的cookie 当中没有给定jsessionid,导致每次都认为是一个新的请求,每次都会生成新的用户数据信息放入到数据库中,逻辑操作变复杂。
增加jsessionid 后:
·TPS:111
·MRT:445ms
·RT90 值:533ms
·应用服务器 CPU 使用率:90% 以上
依然未达到我们的要求,我们继续用JProfiler 查看消耗CPU 的接口,是否还存在问题。这次我们看到,一个请求forward 到jsp 页面,会调用40 多次session.getAttribute。
循环调用问题,开发优化后的性能:
·TPS:165
·MRT:300ms
·RT90 值:373ms
·应用服务器 CPU 使用率:90% 以上
该结果基本满足我们的性能要求,JProfiler 继续查看消耗CPU 的接口时,发现接口的特点是逻辑实现略微复杂,执行内容过多,没有再找到什么可以优化的地方了。
总结
一个小小的接口,花费了大量的时间定位性能差的原因,虽然耗时很久,但是效果还可以。这个接口的一系列定位过程,基本上用到了很多我们常用的定位方法,希望可以给大家后续性能问题定位带来启发。