现象
客户端调用服务时间出现偶尔超时现象
排查
因为服务已开启arthas,使用trace命令监控
$ trace com.lizz slowfun '#cost > 1000' -n 10
- 监控com.lizz类中的slowfun方法,输出用时超过1000ms的记录,记录10条
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 41 ms.
`---ts=2018-12-04 01:12:02;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69`---[1112.033735ms] com.lizz:slowfun()+---[0.006783ms] java.util.Random:nextInt()+---[1111.852594ms] com.lizz:go()`---[0.05447ms] com.lizz:print()
- 记录到com.lizz:go方法用时超过1000ms,继续监控
$ trace com.lizz go '#cost > 1000' -n 10
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 41 ms.
`---ts=2018-12-04 01:12:02;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69`---[1110.033735ms] com.lizz:go()`---[1110.852594ms] com.lizz.UserMapper:select()`---[0.05447ms] com.lizz:print()
- 可以看最终耗时在 com.lizz.UserMapper:select()方法中
- 初步确定为查询数据耗时
排查数据库负载发现,数据库负载存在突刺现象,每5分钟会出现高负载情况。
判断为数据库负载导致的的查询慢问题导致请求响应慢。
修复
解决数据库突刺问题后修复。