慘遭DruidDataSource和Mybatis暗算,致使OOM

時間  2020-01-22
標籤 慘遭 druiddatasource mybatis 暗算 致使 oom 欄目 Java開源 简体版
原文   原文鏈接

先遭DruidDataSource襲擊

事發

一個平凡的工做日，我像往常同樣完成產品提出的需求的業務代碼，忽然收到了監控平臺發出的告警信息。本覺得又是一些業務上的bug致使的報錯，一看報錯發現日誌寫着java.lang.OutOfMemoryError: Java heap space。php

接着我遠程到那臺服務器上，可是卡的不行。因而我就用top命令查了一下cpu信息，佔用都快要到99%了。再看看GC的日誌發現程序一直在Full GC，怪不得cpu佔用這麼高。java

這裏就推測是有內存泄漏的問題致使GC沒法回收內存致使OOM。爲了先不影響業務，就先讓運維把這個服務重啓一下，果真重啓後服務就正常了。git

分析日誌

先看一下報錯日誌詳細寫了一些什麼錯誤信息，雖然通常OOM問題日誌不能準肯定位到問題，可是已經打開日誌平臺了，看一下做爲參考也是不虧的。github

看到日誌中寫的OOM事發場景是在計算多個用戶的總金額的時候出現的，大體僞代碼以下:sql

/**
 * OrderService.java
 */

// 1. 根據某些參數獲取符合條件的用戶id列表
List<Long> customerIds = orderService.queryCustomerIdByParam(param); 

// 2. 計算這些用戶id的金額總和
long principal = orderMapper.countPrincipal(customerIds);
<!-- 

 OrderMapper.xml

-->

<!-- 3. 在OrderMapper的xml文件中寫mybatis的sql邏輯 -->
<select id="countPrincipal" resultType="java.lang.Long">
    select
    IFNULL(sum(remain_principal),0)
    from
    t_loan where
    <if test="null != customerIds and customerIds.size > 0">
        customer_id in
        <foreach collection="customerIds" item="item" index="index" open="("
                 close=")" separator=",">
            #{item}
        </foreach>
    </if>
</select>

這部分感受出問題的緣由是因爲計算金額總額時，查詢參數customerIds太多了。因爲前段時間業務的變動，致使在參數不變的狀況下，查詢出的customerIds列表由原來的幾十幾百個id變成了上萬個，就我看的報錯信息這裏的日誌打印出來這個list的大小就有三萬多個customerId。不過就算查詢條件爲三萬多個而致使sql執行的比較慢，可是這個方法只有內部的財務系統纔會調用，業務量沒那麼大，也不該該致使OOM的出現啊。
因此接着再看一下JVM打印出來的Dump文件來定位到具體的問題。數據庫

分析Dump文件

得益於在JVM參數中加了-XX:+HeapDumpOnOutOfMemoryError 參數，在發生OOM的時候系統會自動生成當時的Dump文件，這樣咱們能夠完整的分析「案發現場」。這裏咱們使用Eclipse Memory Analyzer工具來幫忙解析Dump文件。apache

Snipaste_2020-01-08_16-58-07

從Overview中的餅圖能夠很明顯的看到有個藍色區域佔了最大頭，這個類佔了245.6MB的內存。再看左側的說明寫着DruidDataSource，好的，罪魁禍首就是他了。服務器

Snipaste_2020-01-08_17-15-18

再經過Domainator_Tree界面能夠看到是com.alibaba.druid.pool.DruidDataSource類下的com.alibaba.druid.stat.JdbcDataSourceStat$1對象裏面有個LinkedHashMap，這個Map持有了600多個Entry，其中大約有100個Entry大小爲2000000多字節(約2MB)。而Entry的key是String對象，看了一下String的內容大約都是select IFNULL(sum remain_principal),0) from t_loan where customer_id in (?, ?, ?, ? ...，果真就是剛纔錯誤日誌所提示的代碼的功能。mybatis

問題分析

因爲計算這些用戶金額的查詢條件有3萬多個因此這個SQL語句特別長，而後這些SQL都被JdbcDataSourceStat中的一個HashMap對象所持有致使沒法GC，從而致使OOM的發生。
嗯，簡直是教科書般的OOM事件。多線程

處理

接下來去看了一下JdbcDataSourceStat的源碼，發現有個變量爲LinkedHashMap<String, JdbcSqlStat> sqlStatMap的Map。而且還有個靜態變量和靜態代碼塊:

private static JdbcDataSourceStat global;

static {
    String dbType = null;
    {
    String property = System.getProperty("druid.globalDbType");
    if (property != null && property.length() > 0) {
        dbType = property;
    }
    }
    global = new JdbcDataSourceStat("Global", "Global", dbType);
}

這就意味着除非手動在代碼中釋放global對象或者remove掉sqlStatMap裏的對象，不然sqlStatMap就會一直被持有不能被GC釋放。

已經定位到問題所在了，不過簡單的從代碼上看沒法斷定這個sqlStatMap具體是有什麼做用，以及如何使其釋放掉，因而到網上搜索了一下，發如今其Github的Issues裏就有人提出過這個問題了。每一個sql語句都會長期持有引用，加快FullGC頻率。

sqlStatMap這個對象是用於Druid的監控統計功能的，因此要持有這些SQL用於展現在頁面上。因爲平時不使用這個功能，且詢問其餘同事也不清楚爲什麼開啓這個功能，因此決定先把這個功能關閉。

根據文檔寫這個功能默認是關閉的，不過被咱們在配置文件中開啓了，如今去掉這個配置就能夠了

<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource"
      init-method="init" destroy-method="close">
    ...
    <!-- 監控 -->
    <!-- <property name="filters" value="state"/> -->
</bean>

修改完上線後一段時間後沒有發生OOM了，這時再經過jmap -dump:format=b,file=文件名 [pid]命令生成Dump文件，會發現內存佔用恢復正常，而且也不會看到com.alibaba.druid.pool.DruidDataSource類下有com.alibaba.druid.stat.JdbcDataSourceStat$1的佔用。證實這個OOM問題已經被成功解決了。

再遭Mybatis暗算

事發

又是一個平凡的工做日，線上告警又出現報錯，我一看日誌又是OOM。我覺得上次DruidDataSource問題還沒解決乾淨，可是此次的現象卻有點不同。首先是此次只告警了一次，不像上次一直在告警。而後遠程到服務器看cpu和內存佔用正常，業務也沒有受影響，因此此次也不用重啓服務了。

分析

此次告警的錯誤日誌仍是指向着上次DruidDataSource致使OOM異常的位置，因爲對其印象深入，因此此次直接看看Dump文件(因爲Dump文件比較大，線上的被清除了，而我也忘記備份，因此這份文件是我時候場景還原的時候生成的)。

Snipaste_2020-01-08_22-50-07

此次沒有明顯的一個特別大的佔用對象了，看來此次的問題確實和上次有所不同。再去看看Domainator_Tree界面的具體分析。

Snipaste_2020-01-08_23-01-12

雖然沒有出現一個對象佔用內存，可是能夠看到有十幾個線程都佔用近20M的內存大小，加起來就要佔用300多M的內存了。再看一下這些線程中內存佔用是怎樣的。

Snipaste_2020-01-09_18-10-29

從這個線程的高佔用內存狀況來看，有幾個是String類型的，是拼接SQL後的語句，這些是必不可少的。

還有兩個高內存佔用對象是org.apache.ibatis.scripting.xmltags.DynamicContext$ContextMap和org.apache.ibatis.builder.SqlSourceBuilder$ParameterMappingTokenHandler。

從這兩個對象的內容看彷佛是Mybatis拼接SQL的時候生成的佔位符和參數對象。就好比下面的這個查詢語句

List<Long> customerIds = orderService.queryCustomerIdByParam(param); 

long principal = orderMapper.countPrincipal(customerIds);

因此雖然用於查詢的參數爲Long的類型，即便這個List有三萬多個其自己也不會佔用很大的內存，可是Mybatis在拼接SQL的時候，會把Long類型的對象包裝成一個通用的對象類型(相似於AbstractItem的感受)，而且會給每個通用對象類型起一個別名(好比__frch_item_1, __frch_item_2這樣)，而後存放在Map中在拼接SQL的時候使用。又因爲拼接SQL字符串仍是比較消耗資源，當參數多SQL長的時候仍是須要必定的時間的，這時候Map就會持有較長時間，一旦有較多線程同時作這種操做，內存佔用就高，很容易發生OOM。

查看Mybatis源碼分析

首先看org.apache.ibatis.scripting.xmltags.DynamicContext$ContextMap，他是DynamicContext的一個變量，變量名爲bindings，是DynamicContext的內部類，繼承了HashMap。而且DynamicContext類裏用了bind()方法包裝了HashMap的put()方法。

Snipaste_2020-01-11_15-37-41

再利用IDEA的Usages of查看功能，看看哪些方法調用了bind()方法。

Snipaste_2020-01-12_15-49-45

能夠看到有三個類調用bind()方法，這裏只用關注org.apache.ibatis.scripting.xmltags.ForEachSqlNode這個類，由於咱們在Mybatis的xml裏用了foreach關鍵字來實現SQL的in查詢功能。那咱們大體來看一下ForEachSqlNode這個類有什麼特別的地方可能致使oom的。

ForEachSqlNode實現了SqlNode接口並實現了apply()方法，這個方法是拼接SQL語句的核心，下面是apply()方法的代碼，我爲一些關鍵步驟加了中文註釋。

@Override
  public boolean apply(DynamicContext context) {
      // bindings就是上面說到的佔用大內存的對象
    Map<String, Object> bindings = context.getBindings();
    final Iterable<?> iterable = evaluator.evaluateIterable(collectionExpression, bindings);
    if (!iterable.iterator().hasNext()) {
      return true;
    }
    boolean first = true;
    // SQL的開始字符串
    applyOpen(context);
    int i = 0;
    // 遍歷參數
    for (Object o : iterable) {
      DynamicContext oldContext = context;
      if (first || separator == null) {
        context = new PrefixedContext(context, "");
      } else {
        context = new PrefixedContext(context, separator);
      }
      int uniqueNumber = context.getUniqueNumber();
      // Issue #709
      if (o instanceof Map.Entry) {
        // 若是是Map對象則用key value的形式
        @SuppressWarnings("unchecked")
        Map.Entry<Object, Object> mapEntry = (Map.Entry<Object, Object>) o;
        applyIndex(context, mapEntry.getKey(), uniqueNumber);
        applyItem(context, mapEntry.getValue(), uniqueNumber);
      } else {
        // 以數量i做爲key
        applyIndex(context, i, uniqueNumber);
        applyItem(context, o, uniqueNumber);
      }
      // FilteredDynamicContext動態生成SQL
      contents.apply(new FilteredDynamicContext(configuration, context, index, item, uniqueNumber));
      if (first) {
        first = !((PrefixedContext) context).isPrefixApplied();
      }
      context = oldContext;
      i++;
    }
    // SQL的結束字符串
    applyClose(context);
    context.getBindings().remove(item);
    context.getBindings().remove(index);
    return true;
  }

在每一個遍歷的時候applyIndex()和applyItem()方法就會將參數和參數的佔位符，以及參數SQL先後綴調用上面說的bind()方法存在bindings裏。

private void applyIndex(DynamicContext context, Object o, int i) {
    if (index != null) {
      context.bind(index, o);
      context.bind(itemizeItem(index, i), o);
    }
  }
private void applyItem(DynamicContext context, Object o, int i) {
    if (item != null) {
      context.bind(item, o);
      context.bind(itemizeItem(item, i), o);
    }
  }

接着用FilteredDynamicContext處理佔位符，這是ForEachSqlNode的一個內部類，繼承了DynamicContext類，主要重寫了appendSql()方法。

private static class FilteredDynamicContext extends DynamicContext {
    ...

    @Override
    public void appendSql(String sql) {
      GenericTokenParser parser = new GenericTokenParser("#{", "}", content -> {
        String newContent = content.replaceFirst("^\\s*" + item + "(?![^.,:\\s])", itemizeItem(item, index));
        if (itemIndex != null && newContent.equals(content)) {
          newContent = content.replaceFirst("^\\s*" + itemIndex + "(?![^.,:\\s])", itemizeItem(itemIndex, index));
        }
        return "#{" + newContent + "}";
      });

      delegate.appendSql(parser.parse(sql));
    }

appendSql()用正則來查找替換#{}佔位符裏的內容，但這裏也不是真正的綁定參數，只是替換剛纔存在bindings裏面的佔位符號，例如__frch_item_1, __frch_item_2(在Dump文件中看到的)。

問題分析

由此能夠看出問題是，Mybatis的foreach拼接SQL的性能較差，尤爲是經過正則之類的操做匹配佔位符時須要較多的時間。同時又持有查詢參數和佔位符在ContextMap中沒法被GC釋放，因此一旦併發量上去就很容易內存佔用過多致使OOM。

場景復現

這個問題在本地很容易復現，咱們先建立數據庫表

CREATE TABLE user
(
    id int(11) PRIMARY KEY NOT NULL,
    name varchar(50)
);

建立一個SpringBoot+Mybatis的工程項目。而且模擬線上的JVM配置，在IDEA設置這個工程的VM Option參數-Xmx512m -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError

寫出對應模擬線上的foreach語句

<select id="countUser" resultType="long">
    select
    IFNULL(sum(1),0)
    from user where
    <if test="ids != null and ids.size() > 0">
        id in
        <foreach collection="ids" item="item" index="index" open="("
                 close=")" separator=",">
            #{item}
        </foreach>
    </if>
</select>

再寫單元測試

@Test
public void count() {
    AtomicInteger count = new AtomicInteger(0);
    for (int threadId = 0; threadId < 50; threadId++) {
        // 起50個線程併發調用countUser()方法
        int finalThreadId = threadId;
        new Thread(() -> {
            long userCount = userMapper.countUser(createIds(10000 + finalThreadId));
            log.info("thread:{}, userCount:{}", finalThreadId, userCount);
            count.getAndAdd(1);
        }).start();
    }

    // 等待50個查詢線程跑完
    while (count.get() < 50) {
    }
    log.info("end!!!!");
}

private List<Long> createIds(int size) {
    List<Long> ids = new ArrayList<>();
    for (int i = 0; i < size; i++) {
        ids.add((long) i);
    }
    return ids;
}

接着運行單元測試。因爲在JVM配置加了-XX:+PrintGCDetails參數，因此在控制檯會顯示GC日誌，不一會就會看見不少的Full GC，而後程序就會出現OOM報錯。

Snipaste_2020-01-16_23-20-45

處理

因爲問題是Mybatis經過foreach拼接長SQL字符串性能太差致使的，因此解決思路有兩種

  1. 經過拆分in的查詢條件來減小foreach每次拼接SQL的長度
@Test
public void count2() {
    AtomicInteger count = new AtomicInteger(0);
    for (int threadId = 0; threadId < 50; threadId++) {
        // 起50個線程併發調用countUser()方法
        int finalThreadId = threadId;
        new Thread(() -> {
            List<Long> totalIds = createIds(100000 + finalThreadId);
            long totalUserCount = 0;
            //使用guava對list進行分割,按每1000個一組分割
            List<List<Long>> parts = Lists.partition(totalIds, 1000);
            for (List<Long> ids : parts) {
                totalUserCount += userMapper.countUser(ids);
            }
            log.info("thread:{}, userCount:{}", finalThreadId, totalUserCount);
            count.getAndAdd(1);
        }).start();
    }

    // 等待50個查詢線程跑完
    while (count.get() < 50) {
    }
    log.info("end!!!!");
}

這樣每次拼接查詢SQL的時候只用循環1000次，很快就能夠把資源釋放掉，就不會引發OOM，可是這種方法仍是會生成不少沒必要要的數據佔用內存，頻繁觸發GC，浪費資源。

  1. 不使用Mybatis的foreach來拼接in條件的SQL

既然Mybatis的foreach性能很差，那咱們經過Java層面本身拼接in條件，特別是針對這種查詢條件也比較單一的，更適合本身拼接。

@Test
public void count3() {
    AtomicInteger count = new AtomicInteger(0);
    for (int threadId = 0; threadId < 50; threadId++) {
        // 起50個線程併發調用countUser()方法
        int finalThreadId = threadId;
        new Thread(() -> {
            List<Long> ids = createIds(100000 + finalThreadId);
            StringBuilder sb = new StringBuilder();
            for (long i : ids) {
                sb.append(i).append(",");
            }
            // 查詢條件使用String字符串
            long userCount = userMapper.countUserString(sb.toString());
            log.info("thread:{}, userCount:{}", finalThreadId, userCount);
            count.getAndAdd(1);
        }).start();
    }

    // 等待50個查詢線程跑完
    while (count.get() < 50) {
    }
    log.info("end!!!!");
}
<select id="countUserString" resultType="long">
    select
    IFNULL(sum(1),0)
    from user where
    <if test="null != ids and ids !=''">
        id in (#{ids})
    </if>
</select>

這樣就能大大減小使用foreach而生成的對象，同時減小拼接SQL的時間，避免OOM發生的同時優化性能。

後記

這兩次遇到OOM問題解決起來還算比較輕鬆的，除了後續分析得當之外，也離不開預先的環境配置。在服務JVM參數中增長-XX:+HeapDumpOnOutOfMemoryError和-XX:+PrintGCDetails參數，能夠在發生OOM的時候輸出dump文件，而且能有GC日誌查看GC的具體狀況，這些都是對於OOM問題很是有幫助的。

原文地址:慘遭DruidDataSource和Mybatis暗算,致使OOM

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程