Dlaczego Java G1 gc spędza tyle czasu na skanowanie RS?

Question

Obecnie oceniam odrzutowca G1 i sposób jego wykonywania w naszej aplikacji. Patrząc na GC-dziennik, zauważyłem wiele zbiorów mają bardzo długie „Scan RS” fazy:

7968.869: [GC pause (mixed), 10.27831700 secs] 
    [Parallel Time: 10080.8 ms] 
    (...) 
     [Scan RS (ms): 4030.4 4034.1 4032.0 4032.0 
     Avg: 4032.1, Min: 4030.4, Max: 4034.1, Diff: 3.7] 
     [Object Copy (ms): 6038.5 6033.3 6036.7 6037.1 
     Avg: 6036.4, Min: 6033.3, Max: 6038.5, Diff: 5.2] 
    (...) 
    [Eden: 19680M(19680M)->0B(20512M) Survivors: 2688M->2624M Heap: 
    75331M(111904M)->51633M(115744M)] 
[Times: user=40.49 sys=0.02, real=10.28 secs] 

Wszystkie usunięte dziennika rzędami wpisy pokazujące czasy pracy w jednocyfrowe ms.

Myślę, że większość czasu powinno się spędzić na kopiowaniu, prawda? Jaki może być powód, dla którego skanowanie RS trwa tak długo? Wszelkie pomysły na ulepszenie ustawień G1? JVM rozpoczęto

-Xms40960M -Xmx128G -XX:+UseG1GC -verbose:gc -XX:+PrintGCDetails -Xloggc:gc.log 

EDIT: Aha, zapomniałem ... Używam 7u25 Java

Aktualizacja: Zauważyłem dwie inne dziwne rzeczy:

16187.740: [GC concurrent-mark-start] 
16203.934: [GC pause (young), 2.89871800 secs] 
(...) 
16218.455: [GC pause (young), 4.61375100 secs] 
(...) 
16237.441: [GC pause (young), 4.46131800 secs] 
(...) 
16257.785: [GC pause (young), 4.73922600 secs] 
(...) 
16275.417: [GC pause (young), 3.87863400 secs] 
(...) 
16291.505: [GC pause (young), 3.72626400 secs] 
(...) 
16307.824: [GC pause (young), 3.72921700 secs] 
(...) 
16325.851: [GC pause (young), 3.91060700 secs] 
(...) 
16354.600: [GC pause (young), 5.61306000 secs] 
(...) 
16393.069: [GC pause (young), 17.50453200 secs] 
(...) 
16414.590: [GC concurrent-mark-end, 226.8497670 sec] 

Równoczesny przebieg GC jest kontynuowany podczas wykonywania równoległych przebiegów. Nie jestem pewien, czy to jest zamierzone, ale wydaje mi się to niewłaściwe. Wprawdzie jest to skrajny przykład, ale widzę to zachowanie w całym moim dzienniku.

Inną rzeczą jest to, że mój proces JVM wzrósł do 160g. Biorąc pod uwagę wielkość sterty 128 g, to dość duży narzut. Czy można się tego spodziewać, czy też wycieka pamięć G1? Wszelkie pomysły, jak to znaleźć?

PS: Nie jestem pewien, czy powinien Zrobiłem nowe pytania dotyczące aktualizacji ... jeśli ktoś z was uważa, że ​​byłoby to korzystne, powiedz mi;)

Aktualizacja 2: Przypuszczam, że G1 naprawdę może być przeciekająca pamięć: http://printfdebugger.tumblr.com/post/19142660766/how-i-learned-to-love-cms-and-had-my-heart-broken-by-g1 Jako że jest to przełom na przyszłość, nie zamierzam spędzać więcej czasu na graniu z tym. Rzeczy, których jeszcze nie próbowałem, to konfigurowanie rozmiaru regionu (-XX: G1HeapRegionSize) i obniżanie obłożenia sterty (-XX: InitiatingHeapOccupancyPercent).

Answer 1

Zobaczmy.

1 - Pierwsze wskazówki

Wygląda na to, GC został skonfigurowany do korzystania z 4 wątki (lub masz 4 vCPU, ale jest mało prawdopodobne, biorąc pod uwagę wielkość sterty). Jest dość niski dla sterty 128 GB, spodziewałem się więcej.

Zdarzenia GC wydają się występować w odstępach co 25 sekund. Jednak wyciąg z dziennika, który podałeś, nie wspomina o liczbie przetworzonych regionów.

=> Czy przez jakiś czas określiłeś cele czasu pauzy na G1GC (-XX:MaxGCPauseMillis=N)?

2 - Długi czas skanowania RSET

"Scan RSET" oznacza czas spędzony w GC skanowania zapamiętany sety. Zapamiętywany Zbiór regionu zawiera karty odpowiadające referencjom wskazującym na ten region. Ta faza skanuje te karty, szukając odniesień we wszystkich regionach zbioru kolekcji.

Więc tutaj mamy jeszcze jedno pytanie:

=> Ile regiony były przetwarzane podczas danej kolekcji (czyli jak duży jest cUstaw)

3 - Długi Object skopiować czas

Czas kopiowania, jak sugeruje nazwa, to czas, jaki każdy wątek roboczy kopiuje obiekty na żywo z regionów w Zestawie kolekcji do innych regionów.

Taki długi czas kopiowania może sugerować, że przetworzono wiele regionów i że można zmniejszyć tę liczbę. Może również sugerować zamianę, ale jest to mało prawdopodobne, biorąc pod uwagę twoje wartości użytkownika/wartości rzeczywiste na końcu dziennika.

4 - Teraz co zrobić

Należy sprawdzić w GC zalogować liczbę regionów, które zostały przetworzone. Skoreluj tę liczbę z rozmiarem regionu i określ ilość pamięci, która została zeskanowana.

Następnie można ustawić krótszy czas oczekiwania (na przykład do 500 ms przy użyciu -XX:MaxGCPauseMillis=500). To będzie

• zwiększyć liczbę zdarzeń GC,
• zmniejszyć ilość uwolnionej pamięci w jednym cyklu GC
• zmniejszyć STW pauzuje podczas YGC

nadzieję, że pomoże!

Źródło:

• https://blogs.oracle.com/poonam/entry/understanding_g1_gc_logs
• http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/G1GettingStarted/index.html
• http://jvm-options.tech.xebia.fr/