Dostrajać czy nie dostrajać? G1GC a alokacja olbrzymia

Czym są obiekty olbrzymie?

G1 dzieli całą stertę na regiony. Celem jest uzyskanie 2048 regionów, w przypadku sterty 2GB G1 zastosuje podział na 2048 regionów po 1MB. Rozmiar regionu jest łatwy do ustalenia. Najłatwiej uruchomić (Java 11):

java -Xms2G -Xmx2G -Xlog:gc+heap -version

Java poda rozmiar regionu:

[0.002s][info][gc,heap] Heap region size: 1M

Jeśli chcesz poznać rozmiar regionu po uruchomieniu JVM, możesz użyć jcmd i wielu innych narzędzi:

jcmd <pid> GC.heap_info

Przykładowy wynik:

dateFrom garbage-first heap   total 514048K, used 2048K [0x000000060a000000, 0x0000000800000000)
 region size 2048K, 2 young (4096K), 0 survivors (0K)
Metaspace       used 5925K, capacity 6034K, committed 6272K, reserved 1056768K
 class space    used 500K, capacity 540K, committed 640K, reserved 1048576K

Drugi wiersz zawiera rozmiar regionu.

Obiekty olbrzymie to obiekty przekraczające rozmiar połowy regionu. Są to zwykle duże tablice.

Szczegóły aplikacji

• JDK 11u5 firmy Oracle
• Rozmiar sterty 5GB
• Po dostrojeniu rozmiar regionu został zmieniony na 8MB, więc mamy 640 regionów
• Wspomniane wyżej dostrojenie zostało wykonane w celu uniknięcia fazy Full GC po ostrym wzroście alokacji olbrzymiej. Pomogło, ale nie rozwiązało problemu całkowicie

Przykład wytworzenia tego niepowodzenia

Spójrzmy na rozmiar sterty po kolekcji GC:

Wszystko w normie, poza jednym ostrym wzroście w środku. Spójrzmy na statystyki GC w tabeli:

Mamy jedno wstrzymanie Full GC, numer cyklu 1059. Cykl ten poprzedzały dwa cykle z sytuacjami To-space exhausted (brak miejsca na kopiowanie obiektów przez GC). Spójrzmy na nieprzetworzone logi tekstowe, cykle od 1056 do 1058.

GC(1056) Eden regions: 210->0(319)
GC(1056) Survivor regions: 14->13(28)
GC(1056) Old regions: 233->231
GC(1056) Humongous regions: 0->0
GC(1057) To-space exhausted
GC(1057) Eden regions: 319->0(219)
GC(1057) Survivor regions: 13->5(42)
GC(1057) Old regions: 231->534
GC(1057) Humongous regions: 72->4
GC(1058) To-space exhausted
GC(1058) Eden regions: 97->0(224)
GC(1058) Survivor regions: 5->0(28)
GC(1058) Old regions: 534->636
GC(1058) Humongous regions: 4->4

Oto mały samouczek dotyczący interpretacji tych wierszy:

Wiersz „<type> regions: <from>-><to>(<max>)”, na przykład: „Eden regions: 210->0(319)” oznacza:

• przed cyklem GC liczba regionów wynosiła <from>, 210 w przykładzie powyżej
• po cyklu GC liczba regionów wynosiła <to>, 0 w przykładzie powyżej
• maksymalna liczba regionów w następnym cyklu danego <type> wynosi <max>, 319 Eden w przykładzie powyżej

W cyklu 1056 wszystko było normalnie, a następnie w 1057 mieliśmy 72 nowe obiekty olbrzymie. GC nie udał się proces ewakuacji (zbiór oznaczony jako To-space exhausted) i przeniósł on prawie wszystkie obiekty z młodej generacji do starej. Można to zobaczyć w wierszu ze starymi regionami 231->534, więc pojawiło się 303 nowych starych regionów. Następnie G1 po prostu nie mógł wyczyścić dużej starej generacji w „dostatecznie dobrym” czasie i przeszedł w tryb awaryjny Full GC. Jeśli policzymy wszystkie regiony w cyklu 1057, otrzymamy 319+13+231+72=635 regionów wypełnionych (z 640), więc G1 pozostało tylko 5 regionów na to zadanie. Nic dziwnego, że G1 nie dał rady.

Jeśli spojrzymy na liczbę regionów przed GC, zobaczymy, że był tylko jeden ostry wzrost obiektów olbrzymich w ciągu całego dnia (logi obejmują okres 24 godz.).

Powiedziano mi, że sytuacja zdarza się raz lub dwa razy dziennie w każdym węźle tej aplikacji.

Co możemy zrobić, aby to naprawić?

Jeśli poszukamy odpowiedzi w Google, znajdziemy przede wszystkim sugestie, aby dostroić GC, zwiększając rozmiar regionu. Ale jaki będzie wpływ tego dostrojenia na resztę aplikacji? Tego nikt nie wie. W niektórych sytuacjach można tego spróbować, ale co jeśli obiekt olbrzymi będzie mieć 20MB? Trzeba zwiększyć rozmiar regionu do 64MB, aby obiekt olbrzymi stały się normalnymi obiektami młodej generacji. Niestety nie można tego zrobić, maks. rozmiar regionu wynosi 32MB (JDK 11u9). Inną kwestią do przemyślenia jest czas życia takich obiektów olbrzymich w aplikacji. Jeśli nie jest krótki, będą kopiowane przez kolektor młodej generacji, co może być bardzo kosztowne. Mogą one także zająć większość młodej generacji, co może zwiększyć częstotliwość kolekcji GC.

Aplikacja wspomniana wyżej przeprowadziła takie dostrojenie dwukrotnie. Najpierw zespół programistów zwiększył rozmiar regionu do 4MB, a następnie do 8MB. Problem nadal występuje.

Czy jest coś innego, co możemy zrobić zamiast dostrojenia GC?

Możemy po prostu znaleźć miejsce tworzenia tych obiektów olbrzymich w aplikacji i zmienić kod. Zatem zamiast dostrajać GC, aby lepiej współpracował z aplikacją, możemy zmienić aplikację, aby lepiej współpracowała z GC.

Jak to zrobić?

Jeśli chodzi o obiekt w stosie, są dwa punkty widzenia:

• możemy sprawdzić umiejscowienie obiektu w stosie przy użyciu zrzutu sterty (heap dump)
• albo możemy znaleźć w stos wątku, który tworzy te obiekty przy użyciu profilera alokacji
• albo możemy znaleźć w stos wątku, który tworzy te obiekty poprzez śledzenie wywołań wewnętrznych JVM

Ponieważ chcemy znaleźć miejsce tworzenia obiektów olbrzymich, druga i trzecia opcja są bardziej odpowiednie, ale są sytuacje, w których zrzut sterty jest „dostatecznie dobry”.

Profiler alokacji

Są dwa rodzaje profilerów alokacji:

• profilery, które można uruchamiać w systemach produkcji
• profilery, które obniżają wydajność tak bardzo, ze nie można tego robić

Omówię tylko pierwszy z tych typów. Dwa profilery alokacji, które według mojej wiedzy mogą być używane na produkcji do takich celów, to:

• Async-profiler korzystający z -e alloc (wersja >= 2.0) - open source, w chwili pisania tego artykułu wersja 2.0 była już na etapie „wczesnego dostępu”
• Java Flight Recorder - open source od JDK 11

Korzystają one z tej samej zasady działania. Według pliku readme Async-profiler:

The profiler features TLAB-driven sampling. It relies on HotSpot-specific callbacks to receive two kinds of notifications:

-- when an object is allocated in a newly created TLAB (aqua frames in a Flame Graph);

-- when an object is allocated on a slow path outside TLAB (brown frames).

This means not each allocation is counted, but only allocations every N kB, where N is the average size of TLAB. This makes heap sampling very cheap and suitable for production. On the other hand, the collected data may be incomplete, though in practice it will often reflect the top allocation sources.

Jeśli nie wiesz, czym jest TLAB, polecam przeczytanie tego artykułu. W skrócie: jeden TLAB to mała część eden, który jest przypisany do jednego wątku i w którym możliwa jest alokacja tylko przez jeden wątek.

Oba profilery dostarczają informacji o:

• typ obiektu w alokacji
• stos wątku, w którym utworzono obiekt
• znacznik czasu,
• wątek, który tworzy ten obiekt

Po zrzucie danych konieczne jest przetwarzanie pliku wyjściowego i znalezienie obiektów olbrzymich.

Przykład Async-profiler

Według mnie Async-profiler to najlepszy profiler na świecie, dlatego posłużę się nim w poniższym przykładzie.

Napisana przeze mnie przykładowa aplikacja tworzy alokacje olbrzymie. Spróbujmy znaleźć miejsce wykonywania alokacji. Uruchamiamy (z katalogu async-profiler) polecenie profiler.sh z następującymi parametrami:

• Czas trwania: dziesięć sekund: -d 10
• Plik wyjściowy: -f /tmp/humongous.jfr
• Interesuje nas zdarzenie alokacji, więc: -e alloc
• Application to nasza klasa główna

./profiler.sh -d 10 -f /tmp/humongous.jfr -e alloc Application

Teraz konieczne jest przetwarzanie pliku wyjściowego i znalezienie interesujących stosów. Najpierw spójrzmy na logi GC, aby znaleźć rozmiary:

...
Dead humongous region 182 object size 16777232 start 0x000000074b600000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
Dead humongous region 199 object size 33554448 start 0x000000074c700000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
Dead humongous region 232 object size 67108880 start 0x000000074e800000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
...

Dlatego szukamy obiektów o rozmiarach: 16777232, 33554448, 67108880. Należy pamiętać, że musimy analizować logi z okresu, gdy profiler był uruchomiony. Od wersji 2.0 narzędzia async-profiler JFR wyjściowy jest w wersji 2.0. Możemy użyć narzędzia wiersza poleceń jfr, które zostało dostarczone z JDK 11, do analizy pliku wyjściowego.

Najpierw przeanalizujmy treść pliku wyjściowego:

jfr summary humongous.jfr

Version: 2.0
Chunks: 1
Start: 2020-11-10 07:02:10 (UTC)itit
Duration: 10 s

Event Type                          Count  Size (bytes)
=========================================================
jdk.ObjectAllocationInNewTLAB       65632       1107332
jdk.ObjectAllocationOutsideTLAB       134          2304
jdk.CPULoad                            10           200
jdk.Metadata                            1          4191
jdk.CheckPoint                          1          4449
jdk.ActiveRecording                     1            73
jdk.ExecutionSample                     0             0
jdk.JavaMonitorEnter                    0             0
jdk.ThreadPark                          0             0

Zarejestrowaliśmy:

• 134 alokacji poza TLAB
• 65632 alokacji w nowym TLAB

Obiekty olbrzymie są zwykle alokowane poza TLAB, ponieważ są bardzo duże. Przeanalizujmy te alokacje:

jfr print --events jdk.ObjectAllocationOutsideTLAB humongous.jfr
...
jdk.ObjectAllocationOutsideTLAB {
 startTime = 2020-11-10T07:02:17.329539461Z
 objectClass = byte[] (classLoader = null)
 allocationSize = 16777232
 eventThread = "badguy" (javaThreadId = 37)
 stackTrace = [
   pl.britenet.profiling.demo.nexttry.Application.lambda$main$2() line: 56
   pl.britenet.profiling.demo.nexttry.Application$$Lambda$17.1778535015.run() line: 0
   java.lang.Thread.run() line: 833
 ]
}

jdk.ObjectAllocationOutsideTLAB {
 startTime = 2020-11-10T07:02:17.331986883Z
 objectClass = byte[] (classLoader = null)
 allocationSize = 33554448
 eventThread = "badguy" (javaThreadId = 37)
 stackTrace = [
   pl.britenet.profiling.demo.nexttry.Applic./profiler.sh -d 10 -e "G1CollectedHeap::humongous_obj_allocate" Applicationation.lambda$main$2() line: 56
   pl.britenet.profiling.demo.nexttry.Application$$Lambda$17.1778535015.run() line: 0
   java.lang.Thread.run() line: 833
 ]
}

jdk.ObjectAllocationOutsideTLAB {
 startTime = 2020-11-10T07:02:17.337044969Z
 objectClass = byte[] (classLoader = null)
 allocationSize = 67108880
 eventThread = "badguy" (javaThreadId = 37)
 stackTrace = [
   pl.britenet.profiling.demo.nexttry.Application.lambda$main$2() line: 56
   pl.britenet.profiling.demo.nexttry.Application$$Lambda$17.1778535015.run() line: 0
   java.lang.Thread.run() line: 833
 ]
}
...

Dostępne formaty są następujące:

• Zwykły tekst czytelny dla człowieka - jak w przykładzie powyżej
• JSON
• XML

Domyślnie zrzut stosu jest przycinany do 5 ostatnich ramek. Można to zmienić przy użyciu opcji --stack-depth.

Z powyższych danych wyjściowych możemy odczytać, że mamy 3 obiekty, których szukaliśmy. Możemy odczytać z niego, że alokacja olbrzymia jest wykonywana przez wątek „badguy” i odbywa się w lambdzie w klasie Application.

Śledzenie mechanizmów wewnętrznych JVM

Alokacja olbrzymia odbywa się w g1CollectedHeap.cpp, w ramach:

G1CollectedHeap::humongous_obj_allocate(size_t word_size)

Do śledzenia jej wywołań dostępne są:

• Narzędzia śledzenia z poziomu OS, np. eBPF
• Async-profiler korzystający ze zdarzenia G1CollectedHeap::humongous_obj_allocate. Działa to także w wersji 1.8 (i wcześniejszych)

Przykład Async-profiler

Śledzenie takich wywołań przy użyciu narzędzia async-profiler jest naprawdę łatwe. Musimy uruchomić je z następującymi opcjami:

• Czas trwania: dziesięć sekund: -d 10
• Plik wyjściowy: -f /tmp/humongous.svg (dla wersji 1.8.*, w przypadku 2.* należy użyć rozszerzenia html) dla wyjścia w formacie FlameGraph
• Metoda śledzenia jest przekazywana w -e G1CollectedHeap::humongous_obj_allocate
• Application to nasza klasa główna

./profiler.sh -d 10 -f /tmp/humongous.svg -e G1CollectedHeap::humongous_obj_allocate Application

Możemy zobaczyć alokacje olbrzymie:

Jeśli potrzebujemy nazwy wątku, możemy dodać przełącznik -t podczas uruchamiania narzędzia async-profiler.

Część trudna – modyfikowanie aplikacji

Do tego momentu wszystko było łatwe. Teraz musimy zmodyfikować aplikację. Oczywiście, nie mogę naprawić każdej alokacji olbrzymiej jednym artykułem. Wszystko, co mogę zrobić, to napisać przykłady produkcyjne i opisać wykonane w nich czynności.

Rozproszona pamieć podręczna Hazelcast

Alokacja olbrzymia: Wielkie tablice bajtów rozproszonej pamięci podręcznej Hazelcast podczas rozpraszania między węzłami.

Naprawa: Zmiana dostawcy pamięci podręcznej dla map, w których pojawiała się alokacja olbrzymia. Ogromne tablice bajtów były przesyłane przez sieć, co było zupełnie nieefektywne.

Aplikacja sieciowa - formularz przesyłania do DMS

Alokacja olbrzymia: Aplikacja zawierała formularz HTML, który umożliwiał wysyłanie plików o rozmiarze do 40MB do DMS (system zarządzania dokumentami). Treść tego pliku na poziomie kodu Java to po prostu tablica bajtów. Oczywiście taka macierz była obiektem olbrzymim.

Naprawa: Backend tego formularza przesyłania zostało przeniesione do oddzielnej aplikacji.

Hibernate

Alokacja olbrzymia: Silnik Hibernate tworzył bardzo duże tablice obiektów. Na podstawie zrzutu sterty można było ustalić, jakie były rodzaje obiektów i jakie treści zawierały. Profiler umożliwił ustalenie wątku ich alokacji, a logi aplikacji wywołującą je operację biznesową. Znaleziono definicję klasy w kodzie aplikacji:

@Entity
public class SomeEntity {
   ...
   @OneToMany(fetch = FetchType.EAGER ...)
   private Set<Mapping1> map1;
   @OneToMany(fetch = FetchType.EAGER ...)
   private Set<Mapping2> map2;
   @OneToMany(fetch = FetchType.EAGER ...)
   private Set<Mapping3> map3;
   @OneToMany(fetch = FetchType.EAGER ...)
   private Set<Mapping4> map4;
   @OneToMany(fetch = FetchType.EAGER ...)
   private Set<Mapping5> map5;
   ...
}

Takie mapowanie tworzyło wiele złączeń na poziomie SQL i powielone wyniki, które wymagały przetwarzania przez Hibernate.

Naprawa: W tym obiekcie możliwe było dodanie FetchType.SELECT i właśnie to zrobiono. Należy pamiętać, że w niektórych przypadkach może to spowodować problemy z integralnością danych, dlatego powtarzam: ta zmiana pomogła tej aplikacji, ale może zaszkodzić innej.

Olbrzymie odpowiedzi po WebService

Alokacja olbrzymia: Jedna aplikacja pobierała „katalog produktów” z innej aplikacji przez WebService. Powodowało to tworzenie ogromnej tablicy bajtów (ok. 100MB) do pobierania danych z sieci.

Naprawa: Obie aplikacje zostały zmienione w celu umożliwienia pobierania „katalogu produktów” w kawałkach.

Dostrajać czy nie dostrajać?

Zgodnie z powyższym czasami zamiast dostrajać GC, aby lepiej współpracował z aplikacją, możemy zmienić aplikację, aby lepiej współpracowała z GC. Jakie są zalety i wady?

Zmiana aplikacji - zalety

• Pełna kontrola nad kodem własnej aplikacji umożliwia wprowadzanie dowolnych zmian
• Brak konieczności dogłębnego zrozumienia mechanizmów wewnętrznych JVM. Możliwość wykonania przez własny zespół po analizie.

Zmiana aplikacji - wady

• Wdrożenie
• Zarządzanie wydaniami
• Inne problemy korporacyjne

Dostrojenie GC - zalety

• Wymaga tylko zmiany flag JVM. Czasami wykonalne na produkcji bez wdrożenia.

Dostrojenie GC - wady

• Wymaga dogłębnego zrozumienia mechanizmów wewnętrznych JVM
• Mechanizmy wewnętrzne mogą ulec zmianie z czasem, więc po aktualizacji JDK mogą wystąpić inne problemy z działaniem aplikacji.

Z reguły sugeruję w pierwszej kolejności zmienić aplikację, jeśli może to rozwiązać problemy z GC.