线上性能debug-查看方法级耗时

摘要

可以手动挨个儿方法打debug日志;
可以用AOP集中拦截打日志;
可以用async-profiler查看火焰图;
可以用groovy动态执行benchmark;
可以用arthas的trace命令。

目标(问题背景)

背景是线上某个接口慢,需要优化。为了找到优化的方向,首先需要知道接口的各个部分的耗时,这样才能找到耗时比例最高的部分针对性地优化。
有些时候我们可以使用公司基础架构提供的trace\ rpc monitor来查看rpc调用粒度的耗时;(很多时候慢都是因为某个rpc服务调用慢)
但有些时候我们还是需要知道更细粒度、方法粒度的耗时或者耗时占比, 因为trace中的span一般粒度都是IO调用、如数据库访问、redis访问、rpc调用这种级别。

实操

方法1:每个方法打日志

直接在每个方法开始结束的地方打上debug日志,然后在需要查看耗时的时候,运行时调整日志级别,用arthas:

1
ognl '@com.xxx.spring.BeanFactory@getBean("xxxxServiceImpl").logger.setLevel(@ch.qos.logback.classic.Level@DEBUG)'

这里不一定用com.xxx.spring.BeanFactory, 也可以用某个applicationAware、能拿到applicatoinContext的类,反正只要能用一行代码访问到logger就行。
如果logger所在的bean没有在ApplicationContext里(比如interceptor),可以考虑把logger改成static的。

方法2:AOP集中拦截打日志

这个方法其实算是方法1的简单升级,毕竟每个方法都加上两行开始结束的日志代码量太大,实现上不可能做到。可以用AOP的表达式把所有需要监控的方法都覆盖进去。

这种方法也需要改动代码。

方法3:用async-profiler查看火焰图

前两种方法都需要改动代码,改造成本较高。一个很自然的思路查看耗时占比是我们手动疯狂jstack,统计一下最多次停留的方法,就是耗时占比最高的方法。

代替手动jstack的工具就是https://github.com/jvm-profiling-tools/async-profiler。
可以使用命令(采样30秒):

1
./profiler.sh -d 30 -f time.svg <pid>

有时候会发现意外的耗时瓶颈。(简单的过滤入口操作)
生成的svg文件可以直接用谷歌浏览器打开,可视化的结果,支持点击展开任意层级,非常得方便。

方法4:用groovy脚本动态执行benchmark

有时候线上接口有缓存,阻碍了我们收集p95耗时的瓶颈。这个时候我们可以用groovy脚本动态传入需要执行的java代码。

1
2
3
4
5
6
7
8
// 某个bean中的预留方法:
private Object debug(String code){
String groovyStr = code; // 需要执行的benchmark代码
Binding binding = new Binding();
GroovyShell groovyShell = new GroovyShell(binding);
Script script = groovyShell.parse(groovyStr);
return script.run();
}

这里由于当做脚本语言来用了,安全隐患就是不能让我们以外的人调用,因此如果是内网业务可以鉴权后调用;
外网业务则让可以这个方法没有任何地方调用,需要用的时候我们自己登到机器上用arthas来调用。
(如果黑客入侵到这个程度的话,也无所谓有没有这个方法了)

方法5:用arthas的trace命令

如果不仅需要知道耗时占比,还想知道耗时的具体大小,可以用arthas的trace命令:

1
trace --skipJDKMethod false com.xxx.service.impl.XXXXServiceImpl method1 '#cost > 200'

需要注意一定要加--skipJDKMethod false这个参数,因为我们很多时候用了java8的stream方法,如果跳过了jdk方法的统计,会发现各个子方法的耗时加起来不等于总耗时。

这个不像async-profiler一样能看到所有层级的调用,默认是一层,如果加了这个参数,能看到很多时候耗时最高的方法是 collect方法。

总结

方法3可以看到整个调用栈展开后的耗时占比;
方法4可以构造多次的调用;
方法5只能每次看一层,需要一层一层手动去找,而且官方给的通过listenId增强的方法需要用到telnet,而容器里往往根本没有telnet。因此实际上需要我们一层层去找。

实际工作上往往需要我们结合方法3、4、5。

推荐文章