java►性能

线上性能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。

推荐文章