Minas em desempenho estão esperando nos bastidores: parte 2

Ao preparar o último artigo, um exemplo curioso capturado em um de nossos aplicativos chamou minha atenção. Eu o criei como um artigo separado, que você está lendo no momento.

A essência é extremamente simples: ao criar um relatório e gravá-lo no banco de dados, de tempos em tempos começamos a receber OOME. O erro estava flutuando: em alguns dados, ele era reproduzido constantemente, em outros, nunca era reproduzido.

No estudo de tais desvios, a sequência de ações é clara:

• lançamos o aplicativo em um ambiente isolado com configurações semelhantes a prod, sem esquecer o cobiçado sinalizador -XX:+HeapDumpOnOutOfMemoryError , para que a VM crie um monte de heap quando estiver cheio
• executar ações que levam a uma queda
• pegue o elenco resultante e comece a examiná-lo

Numa primeira aproximação, duas partes iguais de 71 MB são claramente visíveis, e a maior é 6 vezes maior.

O fumo curto da cadeia de chamadas e códigos-fonte ajudou a pontuar todo o "".

 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) 

O projeto usou a combinação usual Spring + Hibernate para essas aplicações. Em algum momento, para estudar as subidas do aplicativo no banco de dados (que é o que faz na maioria das vezes), o DataSource foi envolto em p6spy . Esta é uma biblioteca simples e extremamente útil projetada para interceptar e registrar consultas de banco de dados, bem como medir seu tempo de execução. Seu destaque é a gravação de uma consulta que vai ao banco de dados com todos os argumentos, ou seja, tirar a consulta do log pode executá-la imediatamente no console sem se preocupar com a conversão de argumentos (o Hibernate escreve em vez deles ? ), O que é conveniente ao usar @Convert ou na presença de campos do tipo Date / LocalDate / LocalTime e seus derivados. IMHO, uma coisa extremamente útil na economia do desenvolvedor sangrenta E.

É assim que a entidade que contém o relatório se parece:

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

O uso de uma matriz de bytes é muito conveniente quando uma entidade é usada apenas para salvar / descarregar um relatório, e a maioria das ferramentas para trabalhar com o xslx / pdf pronto para uso suporta a capacidade de criar um livro / documento neste formulário.

E então aconteceu uma coisa terrível e imprevisível: a combinação do Hibernate, uma matriz de bytes e do p6spy se transformou em uma bomba-relógio, que estava passando silenciosamente por enquanto e, quando havia muitos dados, havia explosões.

Como observado acima, ao salvar a entidade, o p6spy interceptou a solicitação e a gravou no log com todos os argumentos. Nesse caso, existem apenas dois deles: a chave e o próprio relatório. Os desenvolvedores do P6spy decidiram que, se o argumento for uma matriz de bytes, seria bom convertê-lo em hexadecimal. Na versão 3.6.0 que estamos usando, isso foi feito assim:

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

Como resultado, algo como isso foi gravado no log

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

Você vê sim? No caso de uma combinação malsucedida de circunstâncias, o seguinte pode aparecer na memória do aplicativo:

• relatório, como uma matriz de bytes
• matriz de caracteres derivada da matriz de bytes
• string obtida da matriz de caracteres obtida da matriz de bytes
• StringBuilder , que inclui uma cópia da sequência obtida da matriz de caracteres obtida da matriz de bytes
• uma sequência que inclui uma cópia da matriz dentro de StringBuilder , que inclui uma cópia da sequência obtida da matriz de caracteres obtida da matriz de bytes.

Nessas condições, um aplicativo de demonstração composto por 2 classes, depois de montado e iniciado no Java 11 (ou seja, com linhas compactadas) com 1 GB de heap, é possível colocar um relatório com apenas 71 MB!

Há duas maneiras de resolver esse problema sem jogar fora o p6spy:

• substitua byte[] por java.sql.Clob (mais ou menos solução, porque os dados não são carregados imediatamente e a confusão com InputStream / OutputStream )
• inclua a propriedade excludebinary=true no arquivo excludebinary=true (ele já foi incluído no aplicativo de teste, você só precisa abri-lo)

Nesse caso, o log de consulta é leve e bonito:

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

Guia de reprodução Consulte README.MD

Conclusões:

• imutabilidade (em particular linhas) vale a pena caro Caro MUITO CARO
• se você tem tabelas com dados confidenciais (aparências, senhas etc.), usa o p6spy e os logs são ruins, então ... bem, você entende
• se você tiver o p6spy e tiver certeza de que será permanentemente / permanentemente, para grandes entidades, faz sentido olhar para @DynamicInsert / @DynamicUpdate . O objetivo é reduzir o volume de logs, criando uma solicitação para cada atualização / inserção individual. Sim, essas consultas serão criadas dinamicamente novamente, mas nos casos em que uma entidade atualizar 1 campo em 20, esse tipo de compromisso pode ser útil. Consulte a documentação para as anotações acima para obter mais informações.

Isso é tudo por hoje :)