VisualVM / Garbage Collector

[swe_et]

Hallo allerseits,

gibt es hier jemanden, der sich mit dem Garbage Collector auskennt? Ich beschäftige mich grade mit einem Problem in einer Webanwendung bzw. versuche ihr Verhalten während des GCollectings zu optimieren. Ich verwende dazu VisualVM (Visual GC Plugin) und kann folgende Situation nicht nachvollziehen. VisualVM weist eine doppelte Anzahl von Old Gen Collections im Vergleich zu Eden Space Collections, wobei ich nie beobachte, dass Old Gen Space voll wird. Mein Verdacht ist, dass VisualVM womöglich die Old Gen Collections falsch interpretiert/anzeigt. Konkreter: ich verwende JVM: Java HotSpot(TM) 64-Bit Server VM (14.1-b02, mixed mode), -XX:+UseConcMarkSweepGC, eine Reihe von anderen Parametern, die jetzt nicht so wichtig sind. Ich logge die Collections mit -verbose:gc. Während ich im VisualVM sehe (hab Tomcat grade durchgestartet):

Eden Space: 1 collections
Old Gen: 2 collections

sehe ich gleichzeitig Folgendes im Log:

21.421: [GC 21.421: [ParNew: 1906560K->95296K(2001856K), 2.2834250 secs] 1906560K->534065K(4000704K), 2.2835150 secs] [Times: user=2.20 sys=0.19, real=2.28 secs]
61.088: [GC [1 CMS-initial-mark: 438769K(1998848K)] 1203686K(4000704K), 0.5620070 secs] [Times: user=0.29 sys=0.01, real=0.57 secs]
61.651: [CMS-concurrent-mark-start]
64.200: [CMS-concurrent-mark: 2.542/2.550 secs] [Times: user=1.83 sys=0.06, real=2.55 secs]
64.200: [CMS-concurrent-preclean-start]
64.263: [CMS-concurrent-preclean: 0.062/0.063 secs] [Times: user=0.03 sys=0.00, real=0.06 secs]
64.263: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time
69.468: [CMS-concurrent-abortable-preclean: 3.045/5.205 secs] [Times: user=1.80 sys=0.00, real=5.20 secs]
69.471: [GC[YG occupancy: 803049 K (2001856 K)]
69.471: [Rescan (parallel) , 0.5799110 secs]70.051: [weak refs processing, 0.0016400 secs] [1 CMS-remark: 438769K(1998848K)] 1241818K(4000704K), 0.5816910 secs]


Man sieht also eine minor collection (1. Zeile), das ist klar, aber der Rest betrifft mMn eine (!) tenured generation collection, wieso zeigt VisualVM 2?? Interpretiere ich etwas falsch?

Danke im Voraus!

Svetlana

 

[EineAntwort]

Ich habe auch schon mehrfach vergeblich nach konkreten Informationen zu Logausgaben des GC gesucht. Der von Dir verwendete JVM-Parameter -verbose:gc könnte für weitergehende Analysen um folgende ergänzt werden:

-XX:+PrintGCDetails -XX:+PrintTenuringDistribution

Die Ausgaben werden dann noch kryptischer und das Rätsel noch spannender. Aber vielleicht helfen die weiteren Angaben ja.

+sven.

 

[jaysch86]

Hi,

versuche mich auch grad am Garbage Collector rumzuspielen. Bin leider blutiger Anfänger in Sachen java. JConsole usw. läuft.
Nun wollte ich mal einen anderen GC ausprobieren und schauen was sich verändert. Hab jetzt versucht die Befehle (z.B. -XX:+UseParallelGC) einfach in die Windows Eingabeaufforderung eingegeben, leider kennt die den Befehl nicht. Muss ich das irgendwo anders machen ?!?

 

[maki]

Bin leider blutiger Anfänger in Sachen java.

Ganz ehrlich: Ignoriere den GC

Gibt es etwas konkretes was du verändern bzw. verbessern möchtest an deiner App?

 

[jaysch86]

Muss ne Projektarbeit zu dem Thema schreiben, bleibt mir leider nichts anderes übrig. Ist ein ERP System das geloggt werden soll. Theoretisch kenn ich mich mittlerweile richtig gut aus, nur an den Tests scheiterts jetzt ein wenig

 

[jaysch86]

Ziel sind vor allem kurze Pausenzeiten, deswegen wollte ich zuerst mal den ConcurrentGC testen, der Parallele sollte ja standardmäßig gesetzt sein.

 

[KSG9|sebastian]

Ich will dir nicht auf die Füße treten, aber wenn du keine JVM mit GC-Parametern starten kannst dann kennst du dich nicht gut aus.

java de.blah.MeineApp -XX:+PrintGCDetails -XX:+PrintTenuringDistribution

Mal den G1 getestet?

-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC

 

[maki]

@jaysch86
JConsole kannst du vergessen,nimm VisualVM.