慎用線程局部變量

最近項目中碰到一個bug，bug出現的原因跟線程局部變量有關，比較典型，這里記錄一下。

Bug場景

SpringBoot web應用，使用通用mapper https://github.com/abel533/Mapper 以及PageHelper https://github.com/pagehelper/Mybatis-PageHelper(mapper-spring-boot-starter版本2.0.2，pagehelper-spring-boot-starter版本1.2.4)做DAL層，測試用例中使用h2內存數據庫。

問題出現在單元測試用例中。項目有多個單元測試類，其中一個叫TaskManagerImplTest，用來做集成測試。報錯的就是這個單元測試類。

Caused by: org.h2.jdbc.JdbcSQLException: Feature not supported: "MVCC=TRUE && FOR UPDATE && GROUP"; SQL statement:
SELECT count(0) FROM general_property WHERE (name = ?) FOR UPDATE [50100-197]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
    at org.h2.message.DbException.get(DbException.java:179)
    at org.h2.message.DbException.get(DbException.java:155)
    at org.h2.message.DbException.getUnsupportedException(DbException.java:228)
    at org.h2.command.dml.Select.queryWithoutCache(Select.java:603)
    at org.h2.command.dml.Query.queryWithoutCacheLazyCheck(Query.java:114)
    at org.h2.command.dml.Query.query(Query.java:371)
    at org.h2.command.dml.Query.query(Query.java:333)
    at org.h2.command.CommandContainer.query(CommandContainer.java:114)
    at org.h2.command.Command.executeQuery(Command.java:202)
    at org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:242)
    at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:498)
    at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:59)
    at com.sun.proxy.$Proxy62.execute(Unknown Source)
    at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:63)
    at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
    at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
    at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:326)
    at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
    at com.github.pagehelper.PageInterceptor.executeAutoCount(PageInterceptor.java:201)
    at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:113)
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
    at com.sun.proxy.$Proxy136.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)

奇怪的是當所有測用例一起執行時，TaskManagerImplTest會出現上面的異常，但單獨執行 TaskManagerImplTest又沒有問題。

解決思路及過程

第一反應可能跟h2的配置有關，查資料發現h2有個配置是控制是否啟用MVCC，嘗試關閉該配置

jdbc:h2:mem:manualtask;MODE=MYSQL;MVCC=false

無效，異常依然出現。

接着嘗試在網上查該問題，沒有發現靠譜的解決方案。於是決定自己分析，跟蹤代碼，查原因。

由於該測試用例單獨執行沒有問題，所有測試用例一起執行有問題，說明應該是其他測試用例對該測試用例產生了影響。通過二分法排除，很快找到引起問題的測試用例，TaskMapperTest類，並通過同樣的方法定位到引起問題方法：

@Test
public void  testSelectByExample() {
    TaskEntity taskModel = new TaskEntity();
    String id = TestUtils.generateUUID();
    String procInstId = TestUtils.generateUUID();
    taskModel.setId(id);
    taskModel.setBusinessKey(TestUtils.generateUUID());
    taskModel.setProcessInstanceId(procInstId);
    taskMapper.insert(taskModel);
    PageHelper.startPage(0, 1);
    Example example = Example.builder(TaskEntity.class).select("source").where(Sqls.custom().andEqualTo("processInstanceId", procInstId)).build();
    List<TaskEntity> taskEntities = taskMapper.selectByExample(example);
    assertTrue(taskEntities.size() > 0);
}

這個方法並不復雜，只是做常規的insert和select測試。其中有一句PageHelper.startPage(0, 1)設置分頁參數，把這一句去掉，測試用例就可以正常運行。

到這里問題已經解決，但解決完問題，事情還沒完。為什么加了分頁，會影響后面其他的測試用例執行呢? 根據PageHelper官方文檔，PageHelper.startPage設置的的線程局部變量，會被后面的第一條查詢消費掉，為啥這里沒有消費呢？於是接下來決定跟蹤代碼，一探究竟。

查看拋出異常的源碼（org.h2.command.dml.Select類的queryWithoutCache方法）：

if (isForUpdateMvcc) {
    if (isGroupQuery) {
        throw DbException.getUnsupportedException(
                "MVCC=TRUE && FOR UPDATE && GROUP");
    } else if (distinct) {
        throw DbException.getUnsupportedException(
                "MVCC=TRUE && FOR UPDATE && DISTINCT");
    } else if (isQuickAggregateQuery) {
        throw DbException.getUnsupportedException(
                "MVCC=TRUE && FOR UPDATE && AGGREGATE");
    } else if (topTableFilter.getJoin() != null) {
        throw DbException.getUnsupportedException(
                "MVCC=TRUE && FOR UPDATE && JOIN");
    }
}

當isForUpdateMvcc和isGroupQuery同時為true時，就拋出上面的異常，那現在的問題就變成這2個變量是在哪設置為true的呢？

繼續跟，找到了設置isForUpdateMvcc的地方：

this.isForUpdate = b;
    if (session.getDatabase().getSettings().selectForUpdateMvcc &&
            session.getDatabase().isMultiVersion()) {
        isForUpdateMvcc = b;
    }
}

這段代碼大意就是如果當前查詢有for update，同時數據庫支持mvcc，而且配置了select for update使用mvcc的話，就設置isForUpdateMvcc為true。 而isGroupQuery會在多個地方設置，這個場景下，因為有select count，所以為true。

出問題的代碼生成的是一句select name, value from general_property where name=? for update語句，但異常信息中報出來有問題的sql是:SELECT count(0) FROM general_property WHERE (name = ?) FOR UPDATE

代碼中並沒有這樣的count語句，那么這條sql是哪來的呢？

繼續分析，發現該sql來自於PageInterceptor類的executeAutoCount方法。

@Override
public Object intercept(Invocation invocation) throws Throwable {
    try {
         …       
        //調用方法判斷是否需要進行分頁，如果不需要，直接返回結果
        if (!dialect.skip(ms, parameter, rowBounds)) {
            …
            if (dialect.beforeCount(ms, parameter, rowBounds)) {
            String countMsId = msId + countSuffix;
            Long count;
            //先判斷是否存在手寫的 count 查詢
            MappedStatement countMs = getExistedMappedStatement(configuration, countMsId);
            if(countMs != null){
                count = executeManualCount(executor, countMs, parameter, boundSql, resultHandler);
            } else {
                countMs = msCountMap.get(countMsId);
                //自動創建
                if (countMs == null) {
                    //根據當前的 ms 創建一個返回值為 Long 類型的 ms
                    countMs = MSUtils.newCountMappedStatement(ms, countMsId);
                    msCountMap.put(countMsId, countMs);
                }
                count = executeAutoCount(executor, countMs, parameter, boundSql, rowBounds, resultHandler);
            }
            //處理查詢總數
            //返回 true 時繼續分頁查詢，false 時直接返回
            if (!dialect.afterCount(count, parameter, rowBounds)) {
                //當查詢總數為 0 時，直接返回空的結果
                return dialect.afterPage(new ArrayList(), parameter, rowBounds);
            }
            }
            …

        } else {
                //rowBounds用參數值，不使用分頁插件處理時，仍然支持默認的內存分頁
                resultList = executor.query(ms, parameter, rowBounds, resultHandler, cacheKey, boundSql);
        }
        return dialect.afterPage(resultList, parameter, rowBounds);
    } finally {
        dialect.afterAll();
    }
}

分析代碼，發現該查詢觸發了分頁，也就是

if (!dialect.skip(ms, parameter, rowBounds)) {

這個判斷為true，沒有跳過分頁。

繼續跟進，發現該方法調用了PageHelper的skip方法。

@Override
public boolean skip(MappedStatement ms, Object parameterObject, RowBounds rowBounds) {
    if(ms.getId().endsWith(MSUtils.COUNT)){
        throw new RuntimeException("在系統中發現了多個分頁插件，請檢查系統配置!");
    }
    Page page = pageParams.getPage(parameterObject, rowBounds);
    if (page == null) {
        return true;
    } else {
        //設置默認的 count 列
        if(StringUtil.isEmpty(page.getCountColumn())){
            page.setCountColumn(pageParams.getCountColumn());
        }
        autoDialect.initDelegateDialect(ms);
        return false;
    }
}

其中Page page = pageParams.getPage(parameterObject, rowBounds); 返回的page不為null，導致觸發分頁。

進入Pageparms類的getPage方法，發現

public Page getPage(Object parameterObject, RowBounds rowBounds) {
Page page = PageHelper.getLocalPage();
if (page == null) {
    if (rowBounds != RowBounds.DEFAULT) {
…

其中Page page = PageHelper.getLocalPage(); 返回的page不為null，而getLocalPage()方法是從線程局部變量中獲取的。 而調用PageHelper.startPage(int, int)方法就會設置該線程局部變量。

@Test
public void  testSelectByExample() {
    TaskEntity taskModel = new TaskEntity();
    String id = TestUtils.generateUUID();
    String procInstId = TestUtils.generateUUID();
    taskModel.setId(id);
    taskModel.setBusinessKey(TestUtils.generateUUID());
    taskModel.setProcessInstanceId(procInstId);
    taskMapper.insert(taskModel);
    PageHelper.startPage(0, 1);
    Example example = Example.builder(TaskEntity.class).select("source").where(Sqls.custom().andEqualTo("processInstanceId", procInstId)).build();
    List<TaskEntity> taskEntities = taskMapper.selectByExample(example);
    assertTrue(taskEntities.size() > 0);
}

到這里，也就找到了為什么加了分頁，會影響后面其他的測試用例的原因。前面提出的第二個問題還沒有找到原因，根據PageHelper官方文檔，PageHelper.startPage設置的的線程局部變量，會被后面的第一條查詢消費掉，為啥這里沒有消費/清除呢？那首先就要看看這個線程局部變量是如何被消費或清除的。

繼續跟蹤代碼，發現這個線程局部變量是在com.github.pagehelper.PageInterceptor的intercept方法中清除的

@Override
public Object intercept(Invocation invocation) throws Throwable {
    try {
        …
    } finally {
        dialect.afterAll();
    }
}

@Override
public void afterAll() {
    //這個方法即使不分頁也會被執行，所以要判斷 null
    AbstractHelperDialect delegate = autoDialect.getDelegate();
    if (delegate != null) {
        delegate.afterAll();
        autoDialect.clearDelegate();
    }
    clearPage();
}

/**
 * 移除本地變量
 */
public static void clearPage() {
    LOCAL_PAGE.remove();
}

該線程局部變量是在finally塊中執行，應該不會出現不執行的情況。所以唯一的可能是整個intercept方法沒執行。

最后，根本原因終於浮出水面。原來，TaskMapperTest配置的spring context只初始化了mapper和數據源，並沒有配置PageHelper插件。因此，TaskMapperTest執行的時候，並沒有執行PageInterceptor的intercept方法；而TaskManagerImplTest測試用例的spring context配置了整個application，啟用了PageInterceptor。這樣就導致TaskMapperTest中設置的線程局部變量沒有被清理掉，TaskManagerImplTest在執行的時候正好取到了，導致本來不需要分頁的請求執行了分頁，才有了select count那句sql。這樣也就解釋了TaskManagerImplTest單獨執行沒有問題，所有測試用例一起執行就有問題的原因。

總結

這個問題一開始看似跟H2有關，但最后的真相跟H2沒有半毛錢關系。該問題的直接原因是PageHelper的使用方法有問題，但從框架的設計角度來說，個人認為通過PageHelper靜態方法設置線程局部變量，然后在PageInterceptor攔截器中使用並不是一種優雅的設計方式，因為這樣的用法並不安全。PageHelper的作者本人也承認這一點，但還是提供了這樣的用法。

線程局部變量在某些情況下可以解決上下文傳遞的麻煩，但使用需要謹慎，盡量避免出現這種在一個地方設置，然后在另一個類的某個地方去清理，而應該盡量采用在一個方法塊中完成變量的設置和清理，就像這樣

try {
    …
    threadLocal.set(value)
    …
} finally {
    threadLocal.remove();
}