Zastanawiam się, czy ktoś jest w stanie wyjaśnić mi, jak interpretować niektóre dzienniki G1 GC, które prowadzą do OutOfMemoryError?Jak interpretować logi G1 GC prowadzące do OutOfMemoryError?
Wiem, że zrzutu sterty najlepiej jest dowiedzieć się, co faktycznie używa sterty, ale nie mogę tego uzyskać, ponieważ zawiera chronione informacje, które nie mogą opuścić strony klienta. Mam tylko dzienniki aplikacji (które zawierają stos z OOME) i dzienniki G1 GC.
Pełne dzienniki G1 GC mają wiele szczegółów, więc nie umieszczę ich tutaj, chyba że ktoś konkretnie musi je zobaczyć.
Specyficzna wersja Java, że pochodzili oni z brzmiała:
> java -version
java version "1.7.0_21"
Java(TM) SE Runtime Environment (build 1.7.0_21-b11)
Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)
i opcje GC używam do tworzenia dziennika GC są:
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xloggc:log/gc.log
Poniżej przedstawiamy wszystkie statystyki pamięci z każdego młody i pełny GC w ciągu ostatnich 30 minut poprzedzających OOME:
INFO | jvm 1 | 2015/05/28 04:29:34 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:33:21 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:37:09 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:40:58 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:44:44 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:48:30 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:52:17 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO | jvm 1 | 2015/05/28 04:52:58 | [Eden: 639M(1290M)->0B(1295M) Survivors: 20M->15M Heap: 2278M(3932M)->1635M(3932M)]
INFO | jvm 1 | 2015/05/28 04:52:59 | [Eden: 51M(1295M)->0B(1300M) Survivors: 15M->10M Heap: 2561M(3932M)->2505M(3932M)]
INFO | jvm 1 | 2015/05/28 04:52:59 | [Full GC 2505M->1170M(3901M), 1.9469560 secs]
INFO | jvm 1 | 2015/05/28 04:53:01 | [Eden: 44M(1300M)->0B(1299M) Survivors: 0B->1024K Heap: 1653M(3901M)->1610M(3901M)]
INFO | jvm 1 | 2015/05/28 04:53:01 | [Eden: 1024K(1299M)->0B(1299M) Survivors: 1024K->1024K Heap: 1610M(3901M)->1610M(3901M)]
INFO | jvm 1 | 2015/05/28 04:53:02 | [Full GC 1610M->1158M(3891M), 1.4317370 secs]
INFO | jvm 1 | 2015/05/28 04:53:03 | [Eden: 112M(1299M)->0B(1296M) Survivors: 0B->1024K Heap: 1758M(3891M)->1647M(3891M)]
INFO | jvm 1 | 2015/05/28 04:53:06 | [Eden: 49M(1296M)->0B(1360M) Survivors: 1024K->1024K Heap: 2776M(4084M)->2728M(4084M)]
INFO | jvm 1 | 2015/05/28 04:53:06 | [Eden: 0B(1360M)->0B(1360M) Survivors: 1024K->1024K Heap: 2837M(4084M)->2836M(4084M)]
INFO | jvm 1 | 2015/05/28 04:53:06 | [Full GC 2836M->1158M(3891M), 1.4847750 secs]
INFO | jvm 1 | 2015/05/28 04:53:08 | [Full GC 1158M->1158M(3891M), 1.5313770 secs]
* To jest di fferent format do surowych logów i usunąłem szczegóły taktowania, aby było krótsze i łatwiejsze do odczytania.
I wykresie również surowe GC rejestruje je w GCViewer:
Wydaje się, że wszystko szło ok do tej pory:
- Zastosowany zwyczajnych była stała (ciemną linię magenta u dołu wykresu).
- Młode przerwy GC występowały co kilka minut, czyszcząc wszystkie młode obiekty (szara linia na górze wykresu).
- Przydzielone rozmiary dla każdego pokolenia były stałe.
- Wykorzystanie sterty po młodych GC było około 1155M.
Następnie na 2015/05/28 04:52:59 rzeczy poszło kształcie gruszki:
- zwyczajnych nagle zaczęły rosnąć.
- Gdy młody GC był prowadzony, w przestrzeni edenów było tylko 51 milionów.
- Występowały pełne wartości GC.
- Pierwsze 3 pełne GCy wydawały się ok, zmniejszyły użycie sterty do 1158M-1170M (co jest bardzo zbliżone do normalnego 1155M).
- Ostateczna pełna GC rozpoczęła się od użycia 1158M i nadal wynosiła 1158M.
Karta pamięci w screenie pokazuje:
Tenured heap (usage/alloc. max) 2,836 (104.1%)/2,723M
Total promotion 2,048K
Teraz pokrótce, co wydarzyło się w 2015/05/28 04:52:59 wyjaśnić. W tym momencie cała paczka obiektów konfiguracyjnych została przekształcona do postaci niestandardowej za pomocą StringBuilder.Spowodowało bandą kopii tablic, które w końcu doprowadziły następującym wyjątkiem w 2015/05/28 04:53:09:
java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:2367)
at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:587)
at java.lang.StringBuilder.append(StringBuilder.java:214)
...
Istnieje kilka rzeczy, których nie można wyjaśnić:
- Gdzie w dziennikach GC można znaleźć zużytą pamięć tymczasową?
- Co spowodowałoby tak znaczny skok wykorzystywanej pamięci stacjonarnej, aby spowodować powstanie GC? Było tylko 20 milionów tych, którzy przeżyli, więc w najgorszym razie nie wszyscy poszliby na służbę i nic więcej?
- Czy może to być wyjaśnione przez ogromną alokację obiektów?
- Dlaczego został wywołany ostatni pełny GC, gdy była (podobno) tak mało używana kupa, a potem nic nie posprzątała?
- Jeśli przydzielono 3891M sterty, a użyto tylko 1158M, to dlaczego miałby istnieć OOME?
Należy uruchomić z '-XX: + PrintGCDetails', aby uzyskać dodatkowe informacje, które GCViewer może przetworzyć – the8472
@ the8472 Tak, właśnie to zrobiłem. Dodałem te szczegóły do pytania. – Steiny
Mam zamiar wypróbować z opcją '-XX: + PrintAdaptiveSizePolicy', aby zobaczyć, czy pokazuje ogromną alokację obiektów. – Steiny