背景
个人维护的一个后台服务使用了Orika框架去处理bean对象之间的映射,并对Orika框架做了简单的封装,减少冗余代码。这里简单说明下Orika框架的原理,Orika框架是在运行时动态创建字节码,生成最小开销的映射器来实现Bean对象之间映射的。其他Bean映射的框架有Mapstruct、BeanCopier等。
问题
后台服务在内部测试环境运行一段时间后,突然发现部分接口响应很慢,而且接口越刷越慢,平均接口耗时十几秒,造成前端接口响应超时,刷不出数据。
问题排查
初步排查
针对相关接口业务逻辑做初步排查后,怀疑耗时主要Orika的bean映射过程。是Orika框架有bug?还是封装的Orika工具类有隐藏的问题?
深入排查
1) 封装的Orika工具类处理Bean映射时耗时突然变长,可能有线程阻塞。
本地启动服务,使用jmeter去本地测试验证,每秒100线程请求并发,循环5次。借助arthas工具,使用thread -b 命令查看当前服务是否有阻塞的线程。
经过测试,确实存在阻塞的线程,由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实现的。
当多个线程同时请求资源临界区时,对象监视器会设置几种状态用来区分请求的线程,涉及线程状态流转可以简单理解下图:
通过线程状态流转可以看出使用了synchronized锁,在并发情况下会有锁等待,这个锁的效率比较低。
由此可以分析,确实因为DefaultMapperFactory.registerClassMap方法阻塞引起的耗时。
但是为什么会不断走到这个动态生成映射器的方法呢?有可能是封装的Orika工具类导致的问题。
3)封装的MapperUtil工具类分析
封装的工具类封装了Orika的基础操作,并缓存了Orika的mapperFacade。
工具类完整代码地址:gitee.com/LuXianSheng…
经过分析,是代码在特殊情况下本地缓存穿透,不断执行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在线分析工具分析,可视化结果如下:
上图主要展示JVM的内存分布,展示了年轻代、老年代、元空间以及JVM给分配的大小和程序运行过程中使用的峰值大小。
上图主要展示jvm的一些关键性指标,如下
- Throughput表示的是吞吐量
- Latency表示响应时间
- Avg Pause GC Time 平均GC时间
- Max Pause GC TIme 最大GC时间
上图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的时候年轻代里面有多少内存(对象)晋升到了老年代。
上图是显示一些GC的统计信息。每种GC总共回收了多少内存、总共用了多长时间、平均时间、以及每种GC的单独统计信息等。
上图显示的是GC的一些原因信息。
通过以上数据分析,可以看出年轻代内存空间不足,申请扩容失败,年轻代GC次数频繁,但是GC后内存回收效果不明显,元数据数据大小有些异常。
5)本地测试验证
本地安装的jdk是1.8,jvm配置是按照默认配置。本地模拟请求100qps,使用jstat -gcutill 命令查询jvm情况
上图可以看到1秒的时间就触发了一次GC,随着QPS不断增加,GC越频繁,实际上应用不应该出现短时间频繁GC。
元数据起初有突峰变化,后面增长缓慢,主要是锁等待导致的。
6)分析
元数据不断的增加,随着请求量越多,元数据会超过阈值,年轻代不断新建映射器的class对象,请求越多,GC的次数越频繁,最终年轻代申请扩容失败OOM 导致接口响应处理越来越慢以及接口响应超时。
结果
综合来看,主要是封装的MapperUtil工具的本地的缓存穿透,不断的执行classMap映射器方法,动态生成很多class类,同时造成synchronized锁争抢和线程阻塞排队等待、jvm的年轻代频繁gc以及元数据的增大,造成结果响应越来越慢。
说明
这边在gitee提交了一个Orika的测试代码,可以复现文章提到的问题,有兴趣的可以本地运行分析验证。
Jemter测试脚本:放在仓库项目中的resource目录
注意事项:一开始可能调用接口很快,没能那么快复现文章提到的问题,因为仓库的项目只是一个测试代码,可以调搞QPS循环测试,可以发现接口响应会越来越慢。
作者:slagsea