一、前言
最近,当新发布的项目上线时,每次重启都会收到机器 CPU 使用率报警,检查相应的监控,持续时间长达 5 分钟,服务重启的风险很大。而且这个项目很多 Consumer 通过多次消费,服务启动后会有大量的线程拉取消息处理逻辑 Jstack 发现输出线程快照有很多 BLOCKED 本文主要记录分析状态线程 BLOCKED 原因。
二、分析过程2.1、初步分析
"consumer_order_status_jmq1714_168429237 #3125 daemon prio=5 os_prio=0 tid=00007fd9eca340000 nid=0x1ca4f waiting for monitor entry [0x00007fd1f3b5000] java.lang.Thread.State: BLOCKED (on object monitor) at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1027) - waiting to lock <0x000000056e822bc8> (a java.util.concurrent.ConcurrentHashMap$Node) at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006) at org.apache.ibatis.type.TypeHandlerRegistry.getJdbcHandlerMap(TypeHandlerRegistry.java:234) at org.apache.ibatis.type.TypeHandlerRegistry.getTypeHandler(TypeHandlerRegistry.java:200) at org.apache.ibatis.type.TypeHandlerRegistry.getTypeHandler(TypeHandlerRegistry.java:191) at org.apache.ibatis.mapping.ParameterMapping$Builder.resolveTypeHandler(ParameterMapping.java:128) at org.apache.ibatis.mapping.ParameterMapping$Builder.build(ParameterMapping.java:103) at org.apache.ibatis.builder.SqlSourceBuilder$ParameterMappingTokenHandler.buildParameterMapping(SqlSourceBuilder.java:123) at org.apache.ibatis.builder.SqlSourceBuilder$ParameterMappingTokenHandler.handleToken(SqlSourceBuilder.java:67) at org.apache.ibatis.parsing.GenericTokenParser.parse(GenericTokenParser.java:78) at org.apache.ibatis.builder.SqlSourceBuilder.parse(SqlSourceBuilder.java:45) at org.apache.ibatis.scripting.xmltags.DynamicSqlSource.getBoundSql(DynamicSqlSource.java:44) at org.apache.ibatis.mapping.MappedStatement.getBoundSql(MappedStatement.java:292) at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:83)at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)at com.sun.proxy.$Proxy232.query(Unknown Source)at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)at sun.reflect.Generatedmethodacesor16.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)at com.sun.proxy.$Proxy124.selectOne(Unknown Source)at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:166)at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59) ...
连续间隔服务 1 分钟使用 Jstack 抓取线程快照,发现有些线程是 BLOCKED 状态可以从堆栈中看出,当前线程被堵塞 ConcurrentHashMap.putVal,而 putVal 该方法内部使用 synchronized 导致当前线程被 BLOCKED,而上一级是 Mybaits TypeHandlerregistry,TypeHandlerRegistry 其功能是记录 Java 类型与 JDBC 类型的相互映射关系,如 java.lang.String 可以映射 JdbcType.CHAR、JdbcType.VARCHAR 等,更上一级是 Mybaits 的 ParameterMapping,而 ParameterMapping 其功能是记录请求参数的信息,包括 Java 类型、JDBC 以及两种类型转换的操作类型 TypeHandler。通过上述信息可以初步定位为并发 Mybaits 对某些参数进行分析,导致大量线程堵塞,需要继续向下分析。
我们可以先回忆一下 Mybatis 启动加载时的一般流程,检查下一个流程将在哪里操作 TypeHandler,会使用 ConcurrentHashMap.putVal 缓存操作?
在 Mybatis 启动过程大致分为以下步骤:
1、XMLConfigBuilder#parseConfiguration() 阅读本地XML文件
2、XMLMapperBuilder#configurationElement() XML文件中的分析 select|insert|update|delete 标签
3、XMLMapperBuilder#parseStatementNode() 开始分析单条 SQL,包括请求参数、返回参数、替换占位符等
4、SqlSourceBuilder 组合单条 SQL 的基本信息
5、SqlSourceBuilder#buildParameterMapping() 请求参数的分析
6、ParameterMapping#getJdbcHandlerMap() 解析 Java 与 JDBC 将映射结果放入缓存类型
而在第 6 步时(图中标色)会得到 Java 对象类型与 JDBC 类型的映射关系,处理过的映射关系 TypeHandler 存储在本地缓存中。然而,堆栈信息仍然触发 TypeHandler 进入缓存的操作,即某个操作 paramType 没有命中缓存,而是在 SQL 实时分析查询时 paramType,线程阻塞是由高并发引起的。下面继续分析一下 sql xml 的配置:
<select id="listxxxByMap" parameterType="java.util.Map" resultMap="BaseResultMap"> select <include refid="Base_Column_List"/> from xxxxx where business_id = #{businessId,jdbcType=VARCHAR} and template_id = #{templateId,jdbcType=INTEGER} </select>
代码请求:
Map<String, Object> params = new HashMap<>();params.put("businessId", "11111");params.put("templateId", "11111");List<TrackingInfo> result = trackingInfoMapper.listxxxByMap(params);
我们没有发现初步的问题,但我们正在进入 TypeHandler 缓存时 debug 下面,分析哪种类型的缓存缺失?
从 debug 从信息中可以看出,TypeHandler 缓存中存在的是 interface java.util.Map,而 SQL 执行过程中传入的是 class java.util.HashMap,导致没有命中缓存。然后我们来修改一下 xml 文件为 parameterType="java.util.HashMap" 解决了吗?
不幸的是,部署后仍然存在问题。
2.2、进一步分析为进一步分析,引入了对照组,而对照组 paramType 为具体 JavaBean。
<select id="listResultMap" parameterType="com.jdwl.xxx.domain.TrackingInfo" resultMap="BaseResultMap"> select <include refid="Base_Column_List"/> from xxxx where business_id = #{businessId,jdbcType=VARCHAR} and template_id = #{templateId,jdbcType=INTEGER} </select>
对照组代码请求
TrackingInfo record = new TrackingInfo();record.setBusinessId("11111");record.setTemplateId(11111);List<TrackingInfo> result = trackingInfoMapper.listResultMap(record);
装载参数 Handler 类 org.apache.ibatis.scripting.defaults.DefaultParameterHandler#setParameters 处进行 debug 分析。
2.2.1、对照组为 listResultMap(paramType=JavaBean)两个参数的分析类型是 StringTypeHandler(红框中的灰色字)与 IntegerTypeHandler(红框中的灰色字),已经是了 Mybatis 提供的 TypeHandler,类型的二次分析没有进行。说明 JavaBean 中的 businessId、templateId 启动时已预先分析了字段。
2.2.2、listxxbyMaplist实验组(paramType=Map)两个参数的分析都是 UnknownTypeHandler(红框中的灰色字),而在 UnknownTypeHandler 中会再次调用 resolveTypeHandler() 方法,对参数类型进行二次分析。可以理解为 Map 属性不是固定类型,只能执行 SQL 再分析一次。
最后修改为 paramType=JavaBean 在部署测试环境后,没有发现重新抓取包。 TypeHandlerRegistry 相关线程堵塞。
三、引申思维既然 paramType 传值会出现堵塞问题,那么 resultType 与 resultMap 有同样的问题吗?继续分为两个实验组:
1、对照组(resultMap=BaseResultMap)
<resultMap id="BaseResultMap" type="com.jdwl.tracking.domain.TrackingInfo"> <id column="id" property="id" jdbcType="BIGINT"/> <result column="template_id" property="templateId" jdbcType="INTEGER"/> <result column="business_id" property="businessId" jdbcType="VARCHAR"/> <result column="is_delete" property="isDelete" jdbcType="TINYINT"/> <result column="create_time" property="createTime" jdbcType="TIMESTAMP"/> <result column="update_time" property="updateTime" jdbcType="TIMESTAMP"/> <result column="ts" property="ts" jdbcType="TIMESTAMP"/> </resultMap><select id="listResultMap" parameterType="com.jdwl.tracking.domain.TrackingInfo" resultMap="BaseResultMap"> select <include refid="Base_Column_List"/> from tracking_info where business_id = #{businessId,jdbcType=VARCHAR} and template_id = #{templateId,jdbcType=INTEGER} </select>
对照组代码请求:
TrackingInfo record = new TrackingInfo();record.setBusinessId("11111");record.setTemplateId(11111);List<TrackingInfo> result1 = trackingInfoMapper.listResultMap(record);
2、实验组(resultType=JavaBean)
<select id="listResultType" parameterType="com.jdwl.tracking.domain.TrackingInfo" resultType="com.jdwl.tracking.domain.TrackingInfo"> select <include refid="Base_Column_List"/> from tracking_info where business_id = #{businessId,jdbcType=VARCHAR} and template_id = #{templateId,jdbcType=INTEGER} </select>
实验组代码请求:
TrackingInfo record = new TrackingInfo();record.setBusinessId("11111");record.setTemplateId(11111);List<TrackingInfo> result2 = trackingInfoMapper.listResultType(record);
返回结果 Handler 处理类 org.apache.ibatis.executor.resultset.DefaultResultSetHandler#createAutomaticMappings() 进行 debug 分析。
1、对照组(resultMap=BaseResultMap)
List 符合预期的标签配置。
2、实验组(resultType=JavaBean)
List标签 id,因此,这些字段被标记为未分析和执行 TypeHandlerRegistry 类型映射逻辑导致并发时线程阻塞。
四、总结1、在使用 paramType 时,xml 需要与配置类型相匹配 Java 使用代码中输入的一致性 Mybatis 预加载时的类型缓存。
2、在使用 paramType 避免使用时间 java.util.HashMap 类型,避免 SQL 执行时解析 TypeHandler。
3、在接收返回值时使用 resultMap,提前映射返回值,减少返回值 TypeHandler 解析。
五、后续在 Mybatis 优化了社区 TypeHandler 进入缓存的逻辑可以解决重复计算 TypeHandler 上述问题在一定程度上得到了缓解。但是 Mybatis 修复的最低版本是 3.5.8,依赖 spring5.x,我们的项目使用 Mybatis3.spring4.4.x,直接升级会有一定的风险,所以在不升级的情况下,按照总结规范使用也可以降低阻塞风险。
TypeHandler 相关issue:<https://github.com/mybatis/mybatis-3/pull/2300/commits/8690d60cad1f397028904fe6056a>
作者:京东物流 钟凯
来源:京东云开发者社区: