Minen unter Leistung warten in den Flügeln: Teil 2

Bei der Vorbereitung des letzten Artikels fiel mir ein merkwürdiges Beispiel in einer unserer Anwendungen auf. Ich habe es als separaten Artikel entworfen, den Sie gerade lesen.

Das Wesentliche ist äußerst einfach: Wenn wir einen Bericht erstellen und in die Datenbank schreiben, erhalten wir von Zeit zu Zeit OOME. Der Fehler schwebte: Bei einigen Daten wurde er ständig reproduziert, bei anderen wurde er nie reproduziert.

Bei der Untersuchung solcher Abweichungen ist die Reihenfolge der Aktionen klar:

• Wir starten die Anwendung in einer isolierten Umgebung mit prod-ähnlichen Einstellungen, ohne das begehrte Flag -XX:+HeapDumpOnOutOfMemoryError , sodass die VM einen Heap des Heaps erstellt, wenn dieser voll ist
• Aktionen ausführen, die zu einem Sturz führen
• Nehmen Sie die resultierende Besetzung und beginnen Sie, sie zu untersuchen

In erster Näherung sind zwei gleiche Stücke von 71 MB deutlich sichtbar, und das größte ist sechsmal größer.

Das kurze Rauchen der Anrufkette und der Quellcodes trug dazu bei, das "" zu markieren.

 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) 

Das Projekt verwendete für solche Anwendungen die übliche Spring + Hibernate-Kombination. Irgendwann wurde die DataSource in p6spy eingeschlossen , um die Wanderungen der Anwendung in der Datenbank zu untersuchen (was meistens der Fall ist) . Dies ist eine einfache und äußerst nützliche Bibliothek, mit der Datenbankabfragen abgefangen und protokolliert sowie deren Ausführungszeit gemessen werden können. Das Highlight ist die Aufzeichnung einer Abfrage, die mit allen Argumenten an die Datenbank gesendet wird, d. H. Wenn die Abfrage aus dem Protokoll entnommen wird, kann sie sofort in der Konsole ausgeführt werden, ohne sich um die Konvertierung von Argumenten zu kümmern (schreibt Hibernate stattdessen ? ). @Convert ist praktisch, wenn Sie @Convert oder verwenden bei Vorhandensein von Feldern vom Typ Date / LocalDate / LocalTime und deren Ableitungen. IMHO, eine äußerst nützliche Sache in der Wirtschaft des Entwicklers Bloody E.

So sieht die Entität aus, die den Bericht enthält:

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

Die Verwendung eines Byte-Arrays ist sehr praktisch, wenn eine Entität nur zum Speichern / Entladen eines Berichts verwendet wird und die meisten Tools zum sofortigen Arbeiten mit xslx / pdf die Möglichkeit unterstützen, ein Buch / Dokument in dieser Form zu erstellen.

Und dann passierte etwas Schreckliches und Unvorhergesehenes: Die Kombination aus Ruhezustand, einer Reihe von Bytes und p6spy verwandelte sich in eine Zeitbombe, die vorerst leise tickte, und wenn es zu viele Daten gab, gab es Explosionen.

Wie oben erwähnt, hat p6spy beim Speichern der Entität die Anforderung abgefangen und mit allen Argumenten in das Protokoll geschrieben. In diesem Fall gibt es nur zwei davon: den Schlüssel und den Bericht selbst. P6spy-Entwickler entschieden, dass es schön wäre, wenn das Argument ein Array von Bytes ist, es in hexadezimal zu konvertieren. In der von uns verwendeten Version 3.6.0 wurde dies folgendermaßen durchgeführt:

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

Infolgedessen wurde so etwas in das Protokoll geschrieben

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

Siehst du, ja? Im Falle einer erfolglosen Kombination von Umständen kann Folgendes im Anwendungsspeicher angezeigt werden:

• Bericht als Array von Bytes
• Zeichenarray vom Byte-Array abgeleitet
• Zeichenfolge aus Zeichenarray aus Bytearray
• StringBuilder , der eine Kopie der Zeichenfolge enthält, die aus dem aus dem Byte-Array erhaltenen Zeichenarray erhalten wurde
• Eine Zeichenfolge, die eine Kopie des Arrays in StringBuilder , die eine Kopie der Zeichenfolge enthält, die aus dem aus dem Byte-Array erhaltenen Zeichenarray erhalten wurde.

Unter diesen Bedingungen können Sie eine Demonstrationsanwendung, die aus 2 Klassen besteht, nach dem Zusammenstellen und Starten auf Java 11 (d. H. Mit komprimierten Zeilen) mit 1 GB Heap einen Bericht mit einem Gewicht von nur 71 MB erstellen!

Es gibt zwei Möglichkeiten, um dieses Problem zu lösen, ohne p6spy wegzuwerfen:

• Ersetzen Sie byte[] durch java.sql.Clob ( java.sql.Clob Lösung, da die Daten nicht sofort geladen werden und die Aufregung mit InputStream / OutputStream ).
• excludebinary=true Datei excludebinary=true Eigenschaft excludebinary=true (sie wurde bereits in der excludebinary=true hinzugefügt, Sie müssen sie nur öffnen.)

In diesem Fall ist das Abfrageprotokoll leicht und schön:

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

Wiedergabeanleitung Siehe README.MD

Schlussfolgerungen:

• Unveränderlichkeit (insbesondere Reihen) ist wert teuer Teuer SEHR TEUER
• Wenn Sie Tabellen mit vertraulichen Daten (Erscheinungsbilder, Kennwörter usw.) haben, verwenden Sie p6spy und die Protokolle sind schlecht, dann ... nun, Sie verstehen
• Wenn Sie p6spy haben und sicher sind, dass es dauerhaft / dauerhaft sein wird, ist es für große Entitäten sinnvoll, sich @DynamicInsert / @DynamicUpdate . Der Punkt besteht darin, das Protokollvolumen zu reduzieren, indem für jede einzelne Aktualisierung / Einfügung eine Anforderung erstellt wird. Ja, diese Abfragen werden jedes Mal im laufenden Betrieb erstellt. In Fällen, in denen eine Entität 1 von 20 Feldern aktualisiert, kann diese Art von Kompromiss hilfreich sein. Weitere Informationen finden Sie in der Dokumentation zu den obigen Anmerkungen.

Das ist alles für heute :)