Mybatis的parameterType造成執行緒阻塞問題分析

2023-06-08 18:00:37

一、前言

最近在新發布某個專案上線時,每次重啟都會收到機器的 CPU 使用率告警,檢視對應監控,持續時長達 5 分鐘,對於服務重啟有很大風險。而該專案有非常多 Consumer 消費,服務啟動後會有大量執行緒去拉取訊息處理邏輯,通過多次 Jstack 輸出執行緒快照發現有很多 BLOCKED 狀態執行緒,此文主要記錄分析 BLOCKED 原因。

二、分析過程

2.1、初步分析

"consumer_order_status_jmq1714_1684822992337" #3125 daemon prio=5 os_prio=0 tid=0x00007fd9eca34000 nid=0x1ca4f waiting for monitor entry [0x00007fd1f33b5000]
   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.GeneratedMethodAccessor160.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、實驗組為listxxxByMap(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 unmappedColumnNames 長度為 0,表示所有欄位都命中了 標籤設定,符合預期。

2、實驗組(resultType=JavaBean)

List unmappedColumnNames 長度為 11,表示所有欄位都在 標籤設定中未找到。這是因為 SQL 執行後的 resultMap 對應的 id 並不等於標籤的 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.4.4,spring4.x,直接升級會存在一定風險,所以在不升級情況下,按照總結規範使用也可以降低阻塞風險。

TypeHandler 相關issue:https://github.com/mybatis/mybatis-3/pull/2300/commits/8690d60cad1f397102859104fee1f6e6056a0593

作者:京東物流 鍾凱

來源:京東雲開發者社群