Na domyślnej konfiguracji, z limitem sterty 1 GB, rampa była jednoznaczna: do około 12 równoczesnych raportów aplikacja działała bez zarzutu, przy 14 sterta się wyczerpywała, a przy 20 połowa żądań kończyła się błędem. Wpisy z logów poniżej cytujemy tak, jak logi je zapisały; uogólnione są tylko ścieżka pliku i adres w nazwie wątku.
Dokładne wpisy z logów
Log aplikacji, application.log, wskazuje miejsce w kodzie CFML: linia 24 to zapytanie czytające z bazy, linie 33 i 36 to budowa struktury raportu w pamięci. Kilka wątków roboczych przewraca się w tej samej sekundzie, co pokazuje, że przyczyną jest równoczesność:
"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"
Log wyjątków, exception.log, potwierdza typ błędu w obu wariantach:
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: GC overhead limit exceeded
Pełny stacktrace w coldfusion-error.log pokazuje szczegół, który ma największe znaczenie. Najwyższe ramki są w sterowniku MariaDB czytającym pakiet wyniku; niżej warstwa zapytań 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)
W chwili błędu żądanie pobierało wynik zapytania i materializowało go w pamięci. Otwarte zapytanie utrzymuje żądanie aktywne, a duży wynik wciągany do sterty przewraca ją, gdy takich żądań jest wiele naraz. Ten sam wzorzec widać w ramkach budujących strukturę raportu, linie 33 i 36: sterta kończy się tam, gdzie akurat przydzielana jest pamięć.
„GC overhead limit exceeded” pojawia się przed „Java heap space”
Logi nie zaczynały się od komunikatu, którego wszyscy szukają. Najpierw, wielokrotnie, pojawiał się inny wariant tego samego błędu, GC overhead limit exceeded. Oznacza on, że garbage collector spędzał ponad 98 procent czasu na odzyskiwaniu mniej niż 2 procent sterty: aplikacja formalnie żyła, a praktycznie stała. Dopiero potem pojawił się twardy Java heap space. Kto przeszukuje logi wyłącznie pod kątem tej frazy, przegapi wcześniejszy i znacznie częstszy sygnał ostrzegawczy.
Błąd uderza poniżej limitu równoczesnych żądań ColdFusion
Błąd wystąpił przy 14 równoczesnych żądaniach, poniżej domyślnego limitu 25 jednoczesnych żądań szablonów. Wniosek jest nieintuicyjny: podniesienie tego limitu nie pomaga, pozwala większej liczbie ciężkich żądań naraz zużywać stertę i przyspiesza awarię. Dławienie żądań nie zastępuje poprawnie dobranej sterty.
Rosnące zużycie pamięci to jeszcze nie wyciek
Po obciążeniu sterta wracała do około 420 MB. Po naprawie, przy dużej stercie, użycie w spoczynku potrafiło pokazywać 4,5 GB, co na pierwszy rzut oka wygląda jak wyciek. Po wymuszonym odśmiecaniu zbiór żywy spadał do około 140 MB; reszta to niezebrane śmieci, bo przy dużej stercie collector się nie spieszy. To rozróżnienie ma znaczenie: gdyby przyczyną był wyciek, większa sterta jedynie odsunęłaby awarię w czasie.
Zrzut pamięci na pełnej partycji to zrzut, którego nie będzie
Włączyliśmy zrzut pamięci przy błędzie braku pamięci, żeby każda przyszła awaria zostawiła plik do analizy. Pułapka: przy stercie 20 GB zrzut może mieć kilkanaście gigabajtów, a partycja systemowa rzadko ma tyle wolnego. Zrzut, którego po awarii potrzeba najbardziej, po cichu by się nie zapisał. Ścieżka zrzutu wskazuje więc wolumen z realnym zapasem miejsca.
Limit 20 GB, a JVM pokazuje 18,2 GB
Po ustawieniu limitu na 20 GB ColdFusion raportował maksymalną stertę około 18 205 MB. To nie błąd ani utracona pamięć: przy równoległym garbage collectorze liczba, którą widzi aplikacja, pomija jedną z przestrzeni survivor. Brakujące dwa gigabajty są na miejscu, tylko nie liczą się do widocznego limitu. Ten sam efekt widać przy domyślnej stercie, która raportuje około 911 MB z 1024, jak opisano w projekcie instalacji.
