DruidDataSource и Mybatis сговорились, что привело к OOM

MyBatis

первыйDruidDataSourceатака

инцидент

В обычный рабочий день я, как обычно, заполнил бизнес-код, требуемый продуктом, и вдруг получил тревожное сообщение от платформы мониторинга. Я думал, что это отчет об ошибке, вызванный какими-то бизнес-ошибками. Когда я увидел отчет об ошибке, я обнаружил, что в журнале говорится:java.lang.OutOfMemoryError: Java heap space.

Потом я удаленно зашел на этот сервер, но карта не работала. Поэтому я используюtopКоманда проверила информацию о ЦП, и занятость составила почти 99%. Посмотрите журнал GC и обнаружите, что программа находилась в режиме полного GC, неудивительно, что загрузка ЦП такая высокая.

Здесь предполагается, что существует проблема с утечкой памяти, из-за которой сборщик мусора не может восстановить память.OOM. Чтобы не влиять на бизнес в первую очередь, позвольте операции и обслуживанию перезапустить службу.Конечно, после перезапуска служба будет работать нормально.

Анализ журналов

Давайте сначала взглянем на журнал ошибок, чтобы увидеть, какие сообщения об ошибках пишутся подробно, хотя в целомOOMЖурнал проблем не может точно определить проблему, но платформа журналов была открыта, и не будет лишним взглянуть на нее как на справку.

посмотри что написано в логеOOMСцена инцидента возникает при подсчете общего количества нескольких пользователей, примерный псевдокод выглядит следующим образом:

/**
 * 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Список изменился с десятков сотен идентификаторов до десятков тысяч.Насколько я вижу здесь сообщение об ошибке, размер списка составляет более 30 000. Журнал распечатывается.customerId. Однако, даже если условий запроса более 30 000 и выполнение sql относительно медленное, этот метод может быть вызван только внутренней финансовой системой, а объем бизнеса не так велик, и он не должен вызыватьOOMвнешний вид. Так что смотри еще разJVMРаспечатайте файл дампа, чтобы найти конкретную проблему.

Анализ файлов дампа

Благодаря добавлению параметров JVM-XX:+HeapDumpOnOutOfMemoryErrorпараметры, возникающиеOOMВ это время система автоматически сгенерирует файл дампа, чтобы мы могли полностью проанализировать «криминальную сцену». Здесь мы используемEclipse Memory AnalyzerИнструменты, помогающие анализировать файлы дампа.

Snipaste_2020-01-08_16-58-07

На круговой диаграмме в обзоре видно, что есть синяя область, занимающая самую большую головку, и этот класс занимает 245,6 МБ памяти. Посмотрите на описание слеваDruidDataSource, хорошо, он виновник.

Snipaste_2020-01-08_17-15-18

Затем через интерфейс Domainator_Tree вы можете увидеть, что этоcom.alibaba.druid.pool.DruidDataSourceпод классcom.alibaba.druid.stat.JdbcDataSourceStat$1В объекте есть LinkedHashMap, эта карта содержит более 600 записей, из которых около 100 записей имеют размер более 2000000 байт (около 2 МБ). Ключ Entry представляет собой объект String, и после просмотра содержимого String речь идет оselect IFNULL(sum remain_principal),0) from t_loan where customer_id in (?, ?, ?, ? ..., это действительно функция кода, подсказанная журналом ошибок только что.

анализ проблемы

Поскольку существует более 30 000 условий запроса для расчета количества этих пользователей, этот оператор SQL очень длинный, и затем эти операторы SQLJdbcDataSourceStatОбъект HashMap в сборщике мусора не может быть удержан, что приводит кOOMслучилось.Ну это как учебникOOMмероприятие.

иметь дело с

Смотри дальшеJdbcDataSourceStat, нашел переменную какLinkedHashMap<String, JdbcSqlStat> sqlStatMapкарта. А еще есть статическая переменная и статический блок кода:

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]Команда создает файл дампа, и вы обнаружите, что использование памяти возвращается к норме, и вы этого не увидите.com.alibaba.druid.pool.DruidDataSourceпод классcom.alibaba.druid.stat.JdbcDataSourceStat$1занятость. доказать этоOOMПроблема была успешно решена.

снова пострадалMybatisучасток

инцидент

Это был очередной обычный рабочий день, и онлайн-будильник снова сообщил об ошибке, я посмотрел в журнал, и это былоOOM. Я думал в прошлый разDruidDataSourceПроблема не решена полностью, но на этот раз явление немного другое. Во-первых, на этот раз он был предупрежден только один раз, в отличие от прошлого раза, когда он был предупрежден всегда. Затем удаленно перейдите на сервер, чтобы убедиться, что загрузка ЦП и памяти в норме, а бизнес не затронут, поэтому на этот раз нет необходимости перезапускать службу.

анализировать

Журнал ошибок этого аварийного сигнала по-прежнему указывает на последний разDruidDataSourceПривести кOOMАномальное расположение очень впечатляет, поэтому на этот раз я смотрю прямо на файл дампа (поскольку файл дампа относительно большой, онлайн-файл был очищен, и я забыл сделать его резервную копию, поэтому этот файл был сгенерирован, когда я восстанавливал сцену .из).

Snipaste_2020-01-08_22-50-07

На этот раз нет явно занятого объекта, особенно большого.Кажется, проблема на этот раз действительно отличается от прошлой. Давайте взглянем на конкретный анализ интерфейса Domainator_Tree.

Snipaste_2020-01-08_23-01-12

Хотя ни один объект не занимает память, можно увидеть, что существует более дюжины потоков, занимающих почти 20 МБ памяти, что в сумме составляет более 300 МБ памяти. Давайте посмотрим на использование памяти этими потоками.

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Их более 30 000, которые сами по себе не займут много памяти, ноMybatisПри склеивании SQL это будетLongОбъекты типа завернуты в общий тип объекта (аналогично поведению AbstractItem), и каждому универсальному типу объекта присваивается псевдоним (например,__frch_item_1, __frch_item_2This), а затем сохраняется в карте для использования при объединении SQL. И поскольку сращивание строк SQL по-прежнему требует больших ресурсов, оно по-прежнему занимает определенное время, когда параметры слишком длинные, а SQL длинный. В это время карта будет удерживаться в течение длительного времени. одновременно с этой операцией потребление памяти будет уменьшено.высокий, легкоOOM.

ПроверитьMybatisАнализ исходного кода

Первый взглядorg.apache.ibatis.scripting.xmltags.DynamicContext$ContextMap,онDynamicContextпеременная с именемbindings,ДаDynamicContextвнутренний класс, который наследуетHashMap. а такжеDynamicContextиспользуется в классеbind()методы обертыванияHashMapизput() метод.

Snipaste_2020-01-11_15-37-41

Повторное использование IDEAUsages ofПосмотрите на функцию, чтобы увидеть, какие методы вызываютсяbind()метод.

Snipaste_2020-01-12_15-49-45

Вы можете видеть, что есть три вызова классаbind()метод, только обратите внимание здесьorg.apache.ibatis.scripting.xmltags.ForEachSqlNodeЭтот класс, потому что мыMybatisизxmlиспользуется вforeachключевое слово для реализации функции запроса SQL. Итак, давайте посмотрим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(как видно из файла дампа).

анализ проблемы

Отсюда видно, что проблема в том,MybatisизforeachПроизводительность объединения SQL низкая, особенно когда требуется больше времени для сопоставления заполнителей с помощью таких операций, как регуляризация. Также содержит параметры запроса и заполнители вContextMapне может быть выпущен GC, поэтому, как только параллелизм увеличивается, легко вызвать слишком много использования памятиOOM.

воспроизведение сцены

Эту проблему легко воспроизвести локально, мы сначала создадим таблицу базы данных

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

СоздаватьSpringBoot+Mybatisинженерный проект. И смоделируйте конфигурацию JVM на линии, задайте проект в IDEAVM 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. Уменьшить, разделив условия запроса на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, но этот метод по-прежнему будет генерировать много ненужных данных, занимающих память, часто запускать сборщик мусора и тратить ресурсы.

  1. Не используйтеMybatisизforeachдля сплайсинга SQL в условии

теперь, когдаMybatisизforeachЕсли производительность неудовлетворительна, то мы сами монтируем условия in через уровень Java, особенно для такого рода условий запроса, которые относительно просты и больше подходят для склейки самостоятельно.

@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Когда файл дампа выводится, и журнал GC можно использовать для просмотра конкретной ситуации GC, они предназначены дляOOMВопросы очень полезны.


Оригинальный адрес:DruidDataSource и Mybatis сговорились, что привело к OOM