Мины под производительностью ждут своего часа: часть 2

При подготовке прошлой статьи от моего внимания ускользнул один любопытный пример, выловленный в одном из наших приложений. Его я оформил в виде отдельной статьи, которую вы сейчас читаете.

Суть предельно проста: при создании отчёта и записи его в базу время от времени мы начали получать ООМЕ. Ошибка была плавающей: на одних данных она воспроизводилась постоянно, на других же не воспроизводилась никогда.

При исследовании такого рода отклонений последовательность действий понятна:

• запускаем приложение в изолированном окружении с продоподобными настройками, не забыв при этом о заветном флаге -XX:+HeapDumpOnOutOfMemoryError, чтобы ВМ создавала слепок кучи при её переполнении
• выполняем действия, ведущие к падению
• берём полученный слепок и начинаем исследовать его

Уже в первом приближении отчётливо видны два равных куска по 71 Мбайт, и самый крупный в 6 раз больше.

Непродолжительное курение цепочки вызовов и исходников помогло расставить все точки над "ё".

Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
  at java.base/java.util.Arrays.copyOf(Arrays.java:3745)
  at java.base/java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:172)
  at java.base/java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:538)
  at java.base/java.lang.StringBuilder.append(StringBuilder.java:174)
  at com.p6spy.engine.common.Value.quoteIfNeeded(Value.java:167)
  at com.p6spy.engine.common.Value.convertToString(Value.java:116)
  at com.p6spy.engine.common.Value.toString(Value.java:63)
  at com.p6spy.engine.common.PreparedStatementInformation.getSqlWithValues(PreparedStatementInformation.java:56)
  at com.p6spy.engine.common.P6LogQuery.logElapsed(P6LogQuery.java:203)
  at com.p6spy.engine.logging.LoggingEventListener.logElapsed(LoggingEventListener.java:107)
  at com.p6spy.engine.logging.LoggingEventListener.onAfterAnyExecute(LoggingEventListener.java:44)
  at com.p6spy.engine.event.SimpleJdbcEventListener.onAfterExecuteUpdate(SimpleJdbcEventListener.java:121)
  at com.p6spy.engine.event.CompoundJdbcEventListener.onAfterExecuteUpdate(CompoundJdbcEventListener.java:157)
  at com.p6spy.engine.wrapper.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:100)
  at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175)
  at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3176)
  at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3690)
  at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:90)
  at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604)
  at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:478)
  at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:356)
  at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
  at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1454)
  at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:511)
  at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3290)
  at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2486)
  at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:473)
  at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:178)
  at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:39)
  at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:271)
  at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:104)
  at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:532)

На проекте использовалась обычная для такого рода приложений связка Спринг + Хибернейт. В какой-то момент для исследования походов приложения в БД (а именно этим оно занимается большую часть времени) DataSource был обёрнут в p6spy. Это простая и чрезвычайно полезная библиотека предназначенная для перехвата и журналирования запросов к БД, а также измерения времени их выполнения. Её изюминкой является запись запроса, уходящего на базу со всеми аргументами, т. е. взяв запрос из лога можно сразу же исполнить его в консоли без возни с преобразованием аргументов (Хибернейт по умолчанию пишет вместо них ?), что удобно при использовании @Convert или при наличии полей типа Date / LocalDate / LocalTime и производных от них. ИМХО, крайне полезная вещь в хозяйстве разработчика кровавого Э.

Вот так выглядит сущность, содержащая отчёт:

@Entity
public class ReportEntity {

  @Id
  @GeneratedValue
  private long id;

  @Lob
  private byte[] reportContent;
}

Использование массива байтов очень удобно, когда сущность используется только для сохранения/выгрузки отчёта, к тому же большинство средств для работы с xslx/pdf из коробки поддерживают возможность создания книги/документа в таком виде.

А дальше произошло страшное и непредвиденное: сочетание Хибернейта, массива байтов и p6spy превратилось в мину замедленного действия, которая тихо тикала до поры до времени, а когда данных стало слишком много — пошли подрывы.

Как отмечено выше, при сохранении сущности p6spy перехватывал запрос и писал его в лог со всеми аргументами. В данном случае их всего 2: ключ и сам отчёт. Разработчики p6spy решили, что если аргументом является массив байтов, то неплохо бы его преобразовать в 16-ричный вид. В используемой нами версии 3.6.0 это делалось так:

// class com.p6spy.engine.common.Value

private String toHexString(byte[] bytes) {
  StringBuilder sb = new StringBuilder();
  for (byte b : bytes) {
    int temp = (int) b & 0xFF;
    sb.append(HEX_CHARS[temp / 16]);
    sb.append(HEX_CHARS[temp % 16]);
  }
  return sb.toString();
}

private String toHexString(byte[] bytes) {
  char[] result = new char[bytes.length * 2];
  int idx = 0;
  for (byte b : bytes) {
    int temp = (int) b & 0xFF;
    result[idx++] = HEX_CHARS[temp / 16];
    result[idx++] = HEX_CHARS[temp % 16];
  }
  return new String(result);
}

В итоге в лог писалось что-то вроде этого

insert into report_entity (report_content, id) values ('6C6F..........7565', 1);

Понимаете, да? При неудачном стечении обстоятельств в памяти приложения одновременно могли оказаться:

• отчёт, в виде массива байтов
• массив знаков, полученный из массива байтов
• строка, полученная из массива знаков, полученного из массива байтов
• StringBuilder, включающий в себя копию строки, полученную из массива знаков, полученного из массива байтов
• строка, включающая в себя копию массива, находящегося внутри StringBuilder-а, включающего в себя копию строки, полученной из массива знаков, полученного из массива байтов.

В этих условиях показательное приложение, состоящее из 2 классов, будучи собранным и запущенным на 11 яве (т. е. со сжатыми строками) с 1 Гбайтом кучи, можно положить отчётом, весящим всего 71 Мбайт!

Есть два способа решить эту проблему, не выбрасывая p6spy:

• заменить byte[] на java.sql.Clob (так себе решение, ведь данные загружаются не сразу и добавляется возня с InputStream / OutputStream)
• добавить свойство excludebinary=true в файл spy.properties (в проверочном приложении оно уже добавлено, нужно только раскрыть его)

В этом случае журнал запросов получается лёгким и красивым:

insert into report_entity (report_content, id) values ('[binary]', 1);

Руководство по воспроизведению см. в README.MD

Выводы:

• неизменяемость (в частности строк) стоит дорого ДОРОГО ОЧЕНЬ ДОРОГО
• если у вас есть таблицы с чувствительными данными (явки, пароли и т. п.), вы используете p6spy, а логи плохо лежат, то… ну вы поняли
• если у вас есть p6spy и вы уверены, что это надолго/навсегда, то для больших сущностей имеет смысл присмотреться к @DynamicInsert/@DynamicUpdate. Смысл в том, чтобы уменьшить объём логов путём создания запроса под каждое отдельное обновление/вставку. Да, эти запросы будут создаваться на лету каждый раз заново, но в тех случаях, когда у сущности обновляется 1 поле из 20 это подобный компромисс может оказаться кстати. Подробнее см. документацию к упомянутым аннотациям.

На сегодня всё :)