Warum verbringt der Java G1 gc so viel Zeit damit, RS zu scannen?

Question

Ich evaluiere gerade den G1 Garbage Collector und wie er für unsere Anwendung funktioniert. Mit Blick auf die gc-log, bemerkte ich eine Menge von Sammlungen haben sehr lange „Scan RS“ Phasen:

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] 

Alle entfernten Log-Zeilen-Einträge zeigen Runtimes im einstelligen ms.

Ich denke die meiste Zeit sollte im Kopieren verbracht werden, oder? Was könnte der Grund sein, dass Scan RS so lange braucht? Irgendwelche Ideen, wie man die G1-Einstellungen optimiert? Die JVM wurde mit

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

bearbeiten begonnen: Oh, ich vergaß ... Ich bin Java 7u25 mit

Update: Ich bemerkte zwei andere seltsame Dinge:

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] 

Der gleichzeitige GC-Lauf wird fortgesetzt, während parallele Läufe ausgeführt werden. Ich bin mir nicht sicher, ob das beabsichtigt ist, aber irgendwie scheint es mir falsch zu sein. Zugegeben, dies ist ein extremes Beispiel, aber ich sehe dieses Verhalten überall in meinem Protokoll.

Eine andere Sache ist, dass mein JVM-Prozess auf 160 g wuchs. Bei einer Heap-Größe von 128g ist das ein ziemlich großer Overhead. Ist das zu erwarten, oder ist G1 Speicherleck vorhanden? Irgendwelche Ideen, wie man das herausfinden kann?

PS: Ich bin nicht wirklich sicher, ob ich für die Updates neue Fragen gemacht haben sollte ... wenn jemand von euch denken, dass dies von Vorteil sein würde, sagen Sie mir;)

Update 2: Ich denke, das G1 kann wirklich undichte Speicher sein: http://printfdebugger.tumblr.com/post/19142660766/how-i-learned-to-love-cms-and-had-my-heart-broken-by-g1 Da dies ein Deal-Breaker für jetzt ist, werde ich nicht mehr Zeit damit verbringen, damit zu spielen. Dinge, die ich noch nicht versucht habe, ist das Konfigurieren der Regionsgröße (-XX: G1HeapRegionSize) und das Verringern der Heapbelegung (-XX: InitiatingHeapOccupancyPercent).

Answer 1

Mal sehen.

1 - Erste Hinweise

Es sieht aus wie wurde Ihre GC konfiguriert 4 Threads zu verwenden (oder Sie haben 4 vCPU, aber es ist unwahrscheinlich, dass die Größe des Haufens gegeben). Es ist ziemlich niedrig für einen 128 GB Heap, ich habe mehr erwartet.

Die GC-Ereignisse scheinen im Intervall von 25+ Sekunden zu erfolgen. Der Protokollauszug, den Sie angegeben haben, erwähnt jedoch nicht die Anzahl der Regionen, die verarbeitet wurden.

=> Haben Sie Pausenzeitziele für G1GC (-XX:MaxGCPauseMillis=N) angegeben?

2 - Lang Scan RSet Zeit

"Scan RSet" bedeutet die Zeit, die GC in Scannen die Remembered Sets ausgegeben. Remembered Der Satz einer Region enthält Karten, die den Referenzen entsprechen, die in diese Region zeigen. Diese Phase scannt diese Karten nach den Referenzen, die auf alle Regionen des Sammlungssatzes zeigen.

Also hier haben wir noch eine Frage:

=> Wie viele Regionen wurden während dieser speziellen Kollektion verarbeitet (dh wie groß ist die CSet)

3 - Lang Object Copy Zeit

Die Kopierzeit ist, wie der Name vermuten lässt, die Zeit, die von jedem Worker-Thread verbraucht wird, um Live-Objekte aus den Regionen im Collection-Set in die anderen Regionen zu kopieren.

Eine so lange Kopierzeit kann darauf hindeuten, dass viele Regionen verarbeitet wurden und dass Sie diese Zahl möglicherweise reduzieren möchten. Es könnte auch Swapping vorschlagen, aber dies ist sehr unwahrscheinlich, wenn Sie Ihre Benutzer-/Real-Werte am Ende des Protokolls angeben.

4 - was nun

Sie tun in der GC überprüfen sollten, um die Anzahl der Regionen protokollieren, die verarbeitet wurden. Korrelieren Sie diese Nummer mit Ihrer Regionsgröße und schließen Sie die Größe des gescannten Speichers ab.

Sie können dann ein kleineres Pausenzeitziel festlegen (z. B. auf 500 ms unter Verwendung von -XX:MaxGCPauseMillis=500). Dies wird

• die Anzahl der GC Ereignisse erhöhen,
• die Menge des freigegebenen Speicher pro GC-Zyklus
• reduzieren die STW Pausen während YGC

Hoffnung reduzieren, das hilft!

Quellen:

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