Mines under performance are waiting in the wings: part 2

In preparing the last article, one curious example caught in one of our applications slipped my attention. I designed it as a separate article, which you are currently reading.

The essence is extremely simple: when creating a report and writing it to the database, from time to time we began to receive OOME. The error was floating: on some data it was reproduced constantly, on others it was never reproduced.

In the study of such deviations, the sequence of actions is clear:

• we launch the application in an isolated environment with prod-like settings, without forgetting about the coveted flag -XX:+HeapDumpOnOutOfMemoryErrorso that the VM creates a heap of the heap when it is full
• perform actions leading to a fall
• take the resulting cast and begin to examine it

In a first approximation, two equal pieces of 71 MB are clearly visible, and the largest is 6 times larger.

Short smoking of the chain of calls and source codes helped to dot all the "ё".

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)

The project used the usual Spring + Hibernate combination for such applications. At some point, to study the application’s hikes in the database (which is what it does most of the time), the DataSource was wrapped in p6spy . This is a simple and extremely useful library designed to intercept and log database queries, as well as measure their execution time. Its highlight is the recording of a query that goes to the database with all arguments, that is, taking a query from the log can immediately execute it in the console without fussing with the conversion of arguments (Hibernate writes instead of them by default ?), which is convenient when using @Convertor in the presence of fields type Date/ LocalDate/LocalTimeand derivatives thereof. IMHO, an extremely useful thing in the economy of the developer bloody E.

This is what the entity containing the report looks like:

@Entity
public class ReportEntity {
  @Id
  @GeneratedValue
  private long id;
  @Lob
  private byte[] reportContent;
}

Using an array of bytes is very convenient when an entity is used only for saving / unloading a report, and most of the tools for working with xslx / pdf out of the box support the ability to create a book / document in this form.

And then a terrible and unforeseen thing happened: the combination of Hibernate, an array of bytes and p6spy turned into a time bomb, which was quietly ticking for the time being, and when there was too much data, there were explosions.

As noted above, while saving the entity, p6spy intercepted the request and wrote it to the log with all the arguments. In this case, there are only 2 of them: the key and the report itself. P6spy developers decided that if the argument is an array of bytes, then it would be nice to convert it to hexadecimal. In the version 3.6.0 we are using, this was done like this:

// 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);
}

As a result, something like this was written to the log

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

You see, yes? Under unfortunate circumstances in the application memory at the same time could be:

• report, as an array of bytes
• character array derived from byte array
• string obtained from character array obtained from byte array
• StringBuilder, which includes a copy of the string obtained from the character array obtained from the byte array
• a string that includes a copy of the array inside StringBuilder-a, which includes a copy of the string obtained from the character array obtained from the byte array.

Under these conditions, a demonstration application consisting of 2 classes, after being assembled and launched on Java 11 (i.e. with compressed lines) with 1 GB of heap, you can put a report weighing only 71 MB!

There are two ways to solve this problem without throwing away p6spy:

• replace byte[]with java.sql.Clob(so-so solution, because the data is not downloaded immediately and fuss is added with InputStream/ OutputStream)
• add a property excludebinary=trueto the file spy.properties(it has already been added to the test application, you just need to open it)

In this case, the query log is light and beautiful:

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

Playback Guide See README.MD

Conclusions:

• immutability (in particular rows) is worth expensiveEXPENSIVE VERY EXPENSIVE
• if you have tables with sensitive data (appearances, passwords, etc.), you use p6spy, and the logs are bad, then ... well, you understand
• if you have p6spy and you are sure that this is for a long time / forever, then for large entities it makes sense to take a closer look at @DynamicInsert/ @DynamicUpdate. The point is to reduce the volume of logs by creating a request for each individual update / insert. Yes, these queries will be created on the fly every time anew, but in cases where an entity updates 1 field out of 20, this kind of compromise may come in handy. See the documentation for the above annotations for more information.

That's all for today :)