Mit der Standardkonfiguration, einem Heap-Limit von 1 GB, war die Rampe eindeutig: Bis etwa 12 gleichzeitige Berichte arbeitete die Anwendung fehlerfrei, bei 14 ging der Heap aus, und bei 20 scheiterte die Hälfte der Anfragen. Die Logeinträge unten sind so zitiert, wie die Logs sie geschrieben haben; verallgemeinert sind nur der Dateipfad und die Adresse im Threadnamen.
Die genauen Logeinträge
Das Anwendungslog, application.log, nennt die Stelle im CFML-Code: Zeile 24 ist die Abfrage, die aus der Datenbank liest, die Zeilen 33 und 36 bauen die Berichtsstruktur im Speicher. Mehrere Arbeitsthreads kippen in derselben Sekunde, was zeigt, dass die Gleichzeitigkeit die Ursache ist:
"Error","ajp-nio-...-exec-1","10/17/26","14:30:21","","Java heap space The specific sequence of files included or processed is: /app/wwwroot/report.cfm, line: 24"
"Error","ajp-nio-...-exec-13","10/17/26","14:30:21","","GC overhead limit exceeded The specific sequence of files included or processed is: /app/wwwroot/report.cfm, line: 36"
"Error","ajp-nio-...-exec-2","10/17/26","14:30:21","","GC overhead limit exceeded The specific sequence of files included or processed is: /app/wwwroot/report.cfm, line: 33"
Das Ausnahmelog, exception.log, bestätigt den Fehlertyp in beiden Varianten:
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: GC overhead limit exceeded
Der vollständige Stacktrace in coldfusion-error.log zeigt das Detail, auf das es ankommt. Die obersten Rahmen liegen im MariaDB-Treiber beim Lesen des Ergebnispakets; darunter die Abfrageschicht von ColdFusion:
SEVERE: Servlet.service() for servlet [CfmServlet] in context with path [] threw exception [ROOT CAUSE:
java.lang.OutOfMemoryError: Java heap space
at org.mariadb.jdbc.client.socket.Reader.readPacket(Reader.java:119)
at org.mariadb.jdbc.client.result.CompleteResult.<init>(CompleteResult.java:100)
at org.mariadb.jdbc.message.ClientMessage.readPacket(ClientMessage.java:373)
at org.mariadb.jdbc.client.impl.StandardClient.readResults(StandardClient.java:1463)
at org.mariadb.jdbc.client.impl.StandardClient.readResponse(StandardClient.java:1382)
at org.mariadb.jdbc.client.impl.StandardClient.execute(StandardClient.java:1306)
at org.mariadb.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:270)
at coldfusion.server.j2ee.sql.JRunPreparedStatement.execute(JRunPreparedStatement.java:98)
at coldfusion.sql.Executive.executeQuery(Executive.java:1461)
at coldfusion.sql.SqlImpl.execute(SqlImpl.java:368)
at coldfusion.tagext.sql.QueryTag.executeQuery(QueryTag.java:1175)
Im Moment des Fehlers holte die Anfrage das Abfrageergebnis und materialisierte es im Speicher. Eine offene Abfrage hält die Anfrage aktiv, und ein großes Ergebnis, in den Heap gezogen, kippt ihn, wenn viele solche Anfragen zugleich laufen. Dasselbe Muster zeigt sich in den Rahmen, die die Berichtsstruktur bauen, Zeilen 33 und 36: Der Heap geht dort aus, wo gerade Speicher angefordert wird.
„GC overhead limit exceeded“ kommt vor „Java heap space“
Die Logs begannen nicht mit der Meldung, nach der alle suchen. Zuerst, viele Male, kam die andere Variante desselben Fehlers, GC overhead limit exceeded. Sie bedeutet, dass der Garbage Collector mehr als 98 Prozent seiner Zeit damit verbrachte, weniger als 2 Prozent des Heaps freizugeben: Die Anwendung lebte formal und stand praktisch. Erst später kam das harte Java heap space. Wer die Logs nur nach dieser Phrase durchsucht, übersieht die frühere und weit häufigere Warnung.
Der Fehler trifft unterhalb des ColdFusion-Limits für gleichzeitige Anfragen
Der Fehler trat bei 14 gleichzeitigen Anfragen auf, unterhalb des Standardlimits von 25 gleichzeitigen Template-Anfragen. Die Folgerung ist nicht intuitiv: Dieses Limit anzuheben hilft nicht, es lässt mehr schwere Anfragen zugleich den Heap nutzen und bringt den Ausfall früher. Anfragen zu drosseln ersetzt keinen richtig bemessenen Heap.
Steigende Speichernutzung ist noch kein Leck
Nach der Last kehrte der Heap auf etwa 420 MB zurück. Nach der Behebung, mit dem großen Heap, konnte die Nutzung in Ruhe 4,5 GB zeigen, was auf den ersten Blick nach einem Leck aussieht. Nach einer erzwungenen Garbage Collection fiel die lebende Menge auf etwa 140 MB; der Rest war nicht eingesammelter Müll, weil der Collector bei einem großen Heap keine Eile hat. Die Unterscheidung zählt: Wäre die Ursache ein Leck gewesen, hätte ein größerer Heap den Ausfall nur verschoben.
Ein Heap-Dump auf einer vollen Partition ist ein Dump, der nie ankommt
Wir haben den Heap-Dump bei einem Out-of-Memory-Fehler eingeschaltet, damit jeder künftige Ausfall eine Datei zur Analyse hinterlässt. Die Falle: Bei einem Heap von 20 GB kann der Dump mehr als zehn Gigabyte groß werden, und die Systempartition hat selten so viel frei. Der Dump, der nach dem Ausfall am meisten gebraucht wird, würde still nicht geschrieben. Der Dump-Pfad zeigt deshalb auf ein Volume mit echter Reserve.
Ein Limit von 20 GB, und die JVM zeigt 18,2 GB
Nachdem das Limit auf 20 GB gesetzt war, meldete ColdFusion einen maximalen Heap von etwa 18 205 MB. Das ist kein Fehler und kein verlorener Speicher: Beim parallelen Garbage Collector lässt die Zahl, die die Anwendung sieht, einen der Survivor-Bereiche aus. Die fehlenden zwei Gigabyte sind da, sie zählen nur nicht zum sichtbaren Limit. Derselbe Effekt zeigt sich beim Standard-Heap, der etwa 911 MB von 1024 meldet, wie im Installationsprojekt beschrieben.
