При подготовке прошлой статьи от моего внимания ускользнул один любопытный пример, выловленный в одном из наших приложений. Его я оформил в виде отдельной статьи, которую вы сейчас читаете.
Суть предельно проста: при создании отчёта и записи его в базу время от времени мы начали получать ООМЕ. Ошибка была плавающей: на одних данных она воспроизводилась постоянно, на других же не воспроизводилась никогда.
При исследовании такого рода отклонений последовательность действий понятна:
- запускаем приложение в изолированном окружении с продоподобными настройками, не забыв при этом о заветном флаге
-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();
}
После вливания двух изменений (тыц и тыц) код выглядит так (текущая версия 3.8.2):
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 это подобный компромисс может оказаться кстати. Подробнее см. документацию к упомянутым аннотациям.
На сегодня всё :)
Автор: tsypanov