Perché Java G1 gc trascorre così tanto tempo nella scansione di RS?

Question

Attualmente sto valutando il garbage collector G1 e come si comporta per la nostra applicazione. Guardando il gc-log, ho notato un sacco di collezioni hanno molto lunghe "Scan RS" fasi:

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] 

Tutti i rimosse log-righe voci mostrano tempi di esecuzione in ms a una cifra.

Penso che la maggior parte del tempo dovrebbe essere speso per la copia, giusto? Quale potrebbe essere la ragione per cui Scan RS impiega così tanto tempo? Qualche idea su come modificare le impostazioni G1? La JVM è stato avviato con

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

Edit: Ah, dimenticavo ... sto usando Java 7u25

Aggiornamento: ho notato altre due cose strane:

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] 

L'esecuzione concomitante del GC prosegue mentre vengono eseguite le esecuzioni parallele. Non sono sicuro che sia intenzionale, ma mi sembra abbastanza sbagliato. Certo, questo è un esempio estremo, ma vedo questo comportamento in tutto il mio registro.

Un'altra cosa è che il mio processo JVM è cresciuto a 160g. Considerando un heap di 128 g, si tratta di un overhead piuttosto ampio. È prevedibile o G1 perde memoria? Qualche idea su come scoprirlo?

PS: Io non sono davvero sicuro se devo aver fatto nuove domande per gli aggiornamenti ... se qualcuno di voi pensa che ciò sia utile, mi dica;)

Update 2: Immagino che il G1 possa davvero perdere memoria: http://printfdebugger.tumblr.com/post/19142660766/how-i-learned-to-love-cms-and-had-my-heart-broken-by-g1 Dato che per ora questo è un rompicapo, non ho intenzione di passare più tempo a giocare con questo. Le cose che non ho ancora provato sono la configurazione della dimensione della regione (-XX: G1HeapRegionSize) e l'occupazione dell'heap (-XX: InitiatingHeapOccupancyPercent).

Answer 1

Vediamo.

1 - Primi indizi

Sembra che la tua GC è stato configurato per utilizzare 4 thread (o si dispone di 4 CPU virtuale, ma è improbabile date le dimensioni del mucchio). È piuttosto basso per un mucchio da 128 GB, mi aspettavo di più.

Gli eventi del GC sembrano verificarsi a intervalli di 25+ secondi. Tuttavia, l'estratto del registro che hai fornito non menziona il numero di regioni che sono state elaborate.

=> Per caso, hai specificato gli obiettivi del tempo di pausa su G1GC (-XX:MaxGCPauseMillis=N)?

2 - Lungo tempo di scansione RSet

"Scan RSet" indica il tempo trascorso il GC nella scansione i set Remembered. Ricordato L'insieme di una regione contiene carte che corrispondono ai riferimenti che puntano in quella regione. Questa fase scansiona quelle carte cercando i riferimenti che puntano in tutte le regioni del set di raccolta.

Così qui, abbiamo ancora una domanda:

=> Quante regioni sono stati elaborati durante quel particolare collezione (cioè quanto grande è il CImpostare)

3 - Long Oggetto Copia tempo

Il tempo di copia, come suggerisce il nome, è il tempo impiegato da ciascun thread di lavoro per copiare oggetti attivi dalle regioni nel Set di raccolta nelle altre regioni.

Un tempo di copia così lungo può suggerire che sono state elaborate molte regioni e che è possibile che si desideri ridurre tale numero. Potrebbe anche suggerire lo swapping, ma questo è molto improbabile dato all'utente/valori reali alla fine del log.

4 - Ora cosa fare

si dovrebbe verificare nel GC registro il numero di regioni che sono stati elaborati. Correla questo numero con la dimensione della tua regione e deduci la quantità di memoria che è stata scansionata.

È quindi possibile impostare un obiettivo di pausa più piccolo (ad esempio, a 500 ms utilizzando -XX:MaxGCPauseMillis=500). Ciò

• aumentare il numero di eventi GC,
• ridurre la quantità di memoria liberata per ciclo GC
• ridurre lo STW pausa durante YGC

Speranza che aiuta!

Fonti:

• 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/