Orika框架封装问题排查

博客讲述了在使用Orika框架进行Bean映射时遇到的性能问题,通过排查发现由于封装的Orika工具类导致的缓存穿透,使得DefaultMapperFactory.registerClassMap方法的synchronized锁引起线程阻塞。此外,JVM的年轻代频繁GC及元数据增长也加剧了问题,最终导致接口响应越来越慢。解决方案涉及优化Orika工具类的缓存策略和调整JVM内存配置。
摘要由CSDN通过智能技术生成

背景

个人维护的一个后台服务使用了Orika框架去处理bean对象之间的映射,并对Orika框架做了简单的封装,减少冗余代码。这里简单说明下Orika框架的原理,Orika框架是在运行时动态创建字节码,生成最小开销的映射器来实现Bean对象之间映射的。其他Bean映射的框架有Mapstruct、BeanCopier等。

问题

后台服务在内部测试环境运行一段时间后,突然发现部分接口响应很慢,而且接口越刷越慢,平均接口耗时十几秒,造成前端接口响应超时,刷不出数据。

问题排查

初步排查

针对相关接口业务逻辑做初步排查后,怀疑耗时主要Orika的bean映射过程。是Orika框架有bug?还是封装的Orika工具类有隐藏的问题?

深入排查

1) 封装的Orika工具类处理Bean映射时耗时突然变长,可能有线程阻塞。

本地启动服务,使用jmeter去本地测试验证,每秒100线程请求并发,循环5次。借助arthas工具,使用thread -b 命令查看当前服务是否有阻塞的线程。

jmeter

Orika阻塞

经过测试,确实存在阻塞的线程,由Orika的DefaultMapperFactory.registerClassMap方法引起了线程阻塞。

2)分析DefaultMapperFactory.registerClassMap源码

这块代码是Orika生成映射器的主要逻辑,方法代码块加了synchronized 重量级锁。

public synchronized <A, B> void registerClassMap(ClassMap<A, B> classMap) {
        this.classMapRegistry.put(new MapperKey(classMap.getAType(), classMap.getBType()), classMap);
        //判断映射器是否正在构建中或者是否已经构建过,若是则重新构建注册
        if (this.isBuilding || this.isBuilt) {
            MappingContext context = this.contextFactory.getContext();
            try {
                if (classMap.getUsedMappers().isEmpty()) {
                    classMap = classMap.copyWithUsedMappers(this.discoverUsedMappers(classMap));
                }
                this.buildMapper(classMap, this.isBuilding, context);
                this.buildObjectFactories(classMap, context);
                this.initializeUsedMappers(classMap);
                this.mapperFacade.factoryModified(this);
            } finally {
                //释放缓存中映射bean的类型、类属性等信息
                this.contextFactory.release(context);
            }
        }
    }

这里简单说下synchronized锁,锁的原理是基于Java 对象头Monitor实现的。

当多个线程同时请求资源临界区时,对象监视器会设置几种状态用来区分请求的线程,涉及线程状态流转可以简单理解下图:

Synchronize

通过线程状态流转可以看出使用了synchronized锁,在并发情况下会有锁等待,这个锁的效率比较低。

由此可以分析,确实因为DefaultMapperFactory.registerClassMap方法阻塞引起的耗时。

但是为什么会不断走到这个动态生成映射器的方法呢?有可能是封装的Orika工具类导致的问题。

3)封装的MapperUtil工具类分析

封装的工具类封装了Orika的基础操作,并缓存了Orika的mapperFacade

工具类完整代码地址:https://gitee.com/LuXianShengTeam/orika-test/blob/master/src/main/java/com/orika/test/util/MapperUtil.kt

经过分析,是代码在特殊情况下本地缓存穿透,不断执行classMapBuilder.byDefault().register() 去注册映射器。核心代码如下:

/**
     * 获取自定义映射
     *
     * @param toClass 映射类
     * @param dataClass 数据映射类
     * @param targetPropertyMap 处理字段名称不一致 (key 原对象属性 value 目标对象属性)
     * @return 映射类对象
     */
    private fun <E, T> getMapperFacade(
            toClass: Class<E>,
            dataClass: Class<T>,
            targetPropertyMap: Map<String, String> = emptyMap(),
            excludes: List<String> = emptyList(),
            converterMap: Map<String, String> = emptyMap()
    ): MapperFacade {
        val mapKey = dataClass.canonicalName + "_" + toClass.canonicalName
        var mapperFacade = CACHE_MAPPER_FACADE_MAP[mapKey]
        //此处缓存穿透
        if (mapperFacade != null && excludes.isEmpty() && converterMap.isEmpty()) {
            return mapperFacade
        }

        //排除属性
        var classMapBuilder = MAPPER_FACTORY.classMap(dataClass, toClass)
        excludes.forEach {
            classMapBuilder = classMapBuilder.exclude(it)
        }

        //属性映射
        targetPropertyMap.forEach {
            val converterId = converterMap[it.key]
            if (converterId != null) {
                classMapBuilder.fieldMap(it.key, it.value).converter(converterId).add()
            } else {
                classMapBuilder.field(it.key, it.value)
            }
        }

        classMapBuilder.byDefault().register()
        mapperFacade = MAPPER_FACTORY.mapperFacade
        CACHE_MAPPER_FACADE_MAP[mapKey] = mapperFacade
        return mapperFacade
    }

问题的主要是原因找到了,可是还存在一个问题,为什么接口会越刷越慢?如果不断注册生成映射器平均耗时是相近的话,应该不会出现很多线程处理在队列排队情况。可以注意到Orika是不断动态生成class加载进jvm,是不是jvm引起的呢?

4) JVM排查

获取服务运行的GC日志,将GC日志通过GCeasy在线分析工具分析,可视化结果如下:

jvm1

上图主要展示JVM的内存分布,展示了年轻代、老年代、元空间以及JVM给分配的大小和程序运行过程中使用的峰值大小。

jvm2

上图主要展示jvm的一些关键性指标,如下

  • Throughput表示的是吞吐量
  • Latency表示响应时间
  • Avg Pause GC Time 平均GC时间
  • Max Pause GC TIme 最大GC时间

jvm3

上图Interactive Graphs展示了运行交互的一些指标数据,如下:

  • Heap after GC:GC之后堆的使用情况
  • Heap before GC:GC之前堆的使用情况
  • GC Duration:GC持续时间
  • Reclaimed Bytes:GC回收掉的垃圾对象的内存大小
  • Young Gen:年轻代堆的使用情况
  • Old Gen:老年代堆的使用情况
  • Meta Space:元空间的使用情况
  • A & P:每次GC的时候堆内存分配和晋升情况。其中红色的线表示每次GC的时候年轻代里面有多少内存(对象)晋升到了老年代。

jvm4

上图是显示一些GC的统计信息。每种GC总共回收了多少内存、总共用了多长时间、平均时间、以及每种GC的单独统计信息等。

jvm5上图显示的是GC的一些原因信息。

通过以上数据分析,可以看出年轻代内存空间不足,申请扩容失败,年轻代GC次数频繁,但是GC后内存回收效果不明显,元数据数据大小有些异常。

5)本地测试验证

本地安装的jdk是1.8,jvm配置是按照默认配置。本地模拟请求100qps,使用jstat -gcutill 命令查询jvm情况

jvm6 jvm7

上图可以看到1秒的时间就触发了一次GC,随着QPS不断增加,GC越频繁,实际上应用不应该出现短时间频繁GC。

测试jvm元数据改

元数据起初有突峰变化,后面增长缓慢,主要是锁等待导致的。

6)分析

元数据不断的增加,随着请求量越多,元数据会超过阈值,年轻代不断新建映射器的class对象,请求越多,GC的次数越频繁,最终年轻代申请扩容失败OOM 导致接口响应处理越来越慢以及接口响应超时。

结果

综合来看,主要是封装的MapperUtil工具的本地的缓存穿透,不断的执行classMap映射器方法,动态生成很多class类,同时造成synchronized锁争抢和线程阻塞排队等待、jvm的年轻代频繁gc以及元数据的增大,造成结果响应越来越慢。

说明

这边在gitee提交了一个Orika的测试代码,可以复现文章提到的问题,有兴趣的可以本地运行分析验证。

仓库地址:https://gitee.com/LuXianShengTeam/orika-test

Jemter测试脚本:放在仓库项目中的resource目录

注意事项:一开始可能调用接口很快,没能那么快复现文章提到的问题,因为仓库的项目只是一个测试代码,可以调搞QPS循环测试,可以发现接口响应会越来越慢。

评论 3
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

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

抵扣说明:

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

余额充值