一个小插件引起的性能问题排查和解决过程

74 篇文章 9 订阅
29 篇文章 0 订阅

事情是这样的

过年期间闲的没事,用MyBatis的拦截器插件做了一个小功能,来专门处理新项目中的审计字段。

本来还在开开心心地摸鱼,结果压测团队的同事就找上门来啦,说我的的应用接口的TPS突然降低很多,是不是有BUG呀~ 是有BUG呀~ BUG呀~ 呀~

emmm...大过年的,晦气!

最近也没上啥特殊的功能呀,就搞了一个插件,还能出这问题?

于是,就开始排查呗。

问题定位

工具jvisualVm

因为我们有一套专门的压测环境,并且是开启JMX配置的,所以我直接本地连上压测环境的JVM主机,进行一波分析。

先给大家安利这个工具,早用早爽。

jvisualVm是JDK自带的一款工具,能够监控线程,内存情况,查看方法的CPU时间和内存中的对 象,已被GC的对象,反向查看分配的堆栈等,并且使用非常简单,并且功能丰富,包含其他JDK自带命令的大部分功能。

jvisualVm就放在JDK的bin目录里,双击打开就可以使用。

打开后在左侧右键远程添加远程主机。

主机名对应你要连的远程主机IP,端口处指定远程JVM开启的JMX端口。前提是你的远程JVM开启了JMX。

然后在主机上添加JMX连接。

然后打开JMX连接后,就可以看到下图效果。

可以对CPU,内存,线程等进行实时监控。

工具基本介绍完了,接下来用这个神器排查一下问题到底出在哪里。

抽样器查看热点方法

我采用的方法是使用jvisualVm的抽样器直接查看压测时的热点方法的耗时情况。

在这个结果中,排在最上面的,表示在这个时间段内,花费时间最长的方法。

显而易见,IbatisAuditDataInterceptor.intercept()这个方法花费了34.7%

定位到具体的方法了,接下来看看为啥慢吧。

代码分析

方面阅读,这里先贴一下代码。

这里你不妨也先看一下是什么导致的慢。

代码逻辑相对还是比较简单的,就是一些循环和判断,和一些赋值动作,而循环的数据是可以肯定数据量并不大的。

比较特殊的一点是,这里的赋值使用的是org.apache.commons.beanutils.BeanUtils.setProperty()实现的。

怀疑是因为这里使用了反射,导致设置属性值的时间很长导致

问题解决

初步对问题代码有了定位之后,我们可以修改一下试试。

知道是因为反射的原因导致变慢了,那我们有什么办法能让这里设置属性效率更快呢?

当然是用setter方法直接设置的效率最快,但是这里我考虑到后期可能要在不同的应用中集成,而不同应用的审计字段命名可能会有区别,要进行配置化,所以还是要通过反射来做。

接下来,又要安利好东西了。

ReflectAsm

ReflectAsm是一款高性能的反射工具包相比较于JDK原生的反射获得Mehtod执行,和Apache的BeanUtils来说,它的性能要高很多。

使用ReflectAsm需要先引入依赖,以Maven为例:

<dependency>
    <groupId>com.esotericsoftware</groupId>
    <artifactId>reflectasm</artifactId>
    <version>1.11.0</version>
</dependency>

看它的Jar包的话很简单,只有5个类:

如果要反射调用方法的话只需要用到ConstructorAccessMethodAccess

先通过一个小测试来体验一下ReflectAsm效率的强悍。

public class ReflectDemo {

    public static void main(String[] args) throws InvocationTargetException, IllegalAccessException {
        MethodAccess methodAccess = MethodAccess.get(User.class);
        User user = new User();

        long start, end;

        start = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            user.setName("小黑说");
        }
        end = System.currentTimeMillis();
        System.out.println("setter花费时间:"+(end-start));

        start = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            methodAccess.invoke(user, "setName", "小黑说");
        }
        end = System.currentTimeMillis();
        System.out.println("methodAccess花费时间:"+(end-start));

        start = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            BeanUtils.setProperty(user, "setName", "小黑说");
        }
        end = System.currentTimeMillis();

        System.out.println("BeanUtils花费时间:"+(end-start));

    }
}

@Data
class User {
    private String name;
}

上面代码逻辑是通过直接调用set方法,使用MethodAccessBeanUtils分别对User对象设置name属性1,000,000次,运行时间如下:

setter花费时间:21
methodAccess花费时间:69
BeanUtils花费时间:21256

从结果上看,set方法肯定花费时间最少,MethodAccess相比set方法花费的时间要多一点,注意这是100万次运行花费的时间。

BeanUtils相比就要慢的多,花费了21256ms,差距有百倍之多。

这样看来,使用ReflectAsm应该可以让我们的插件执行花费的时间变少很多,来改造一下吧。

除了将反射调整为METHOD_ACCESS外,并将重复的代码抽取到两个方法中。

重新提交代码进行压测后,问题得到了解决,又可以愉快地摸鱼啦。

最后

以上是小编进行一次小问题排查和改造的记录,希望能够对你遇到类似问题时有所帮助。

本文还主要给大家安利两个工具。

一个是jvisualVm,可以用来进行内存,GC,线程等问题的排查;

另外是一款高性能反射工具ReflectAsm,大家以后如果需要进行反射操作时,可以优先使用。

我是老猿,一名在互联网“苟且”的程序员,有一个公众号【清朝程序猿】

给粉丝们的福利:1.关注公众号不定时送书  2.分享自己的一些学习资料,面试题等等  3.有什么不懂的问题也可以随时问我

 

  • 0
    点赞
  • 1
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值