Sammlung CMS Müll zu lange

Question

Einer unserer Kunden läuft in großen Performance-Probleme, die durch lange Garbage Collection läuft verursacht zu sein scheinen, und ich weiß nicht, was zu tun ist ...

Java-Version: 1.7 .0_67 JVM args: -Xms10240m -Xmx16386m -XX: NewSize = 2048m -XX: MaxPermSize = 150m -XX: + UseParNewGC -XX: + UseConcMarkSweepGC -XX: + PrintGCDetails ...

Zusatzinfo

Die Anwendung ist unser Server-Backend für eine Webanwendung. Der Server stellt eine Verbindung zu einer SQL-Datenbank und mehreren ERP-Systemen her. Diese Daten werden dann verarbeitet und an die Web-Clients gesendet. Gerade dieser Kunde hat weltweit rund 50 Nutzer, die über diesen Single-Server auf Daten zugreifen.

• OS: Windows Server 2008 R2 Datacenter + SP1
• CPU: Xeon E5-2660 (4 Cores + HT)
• RAM: 32 GB

Was ich versucht habe, so weit

• erhöht Xmx und Xms (gelesen, dass Xms identisch sein sollte oder zumindest in der Nähe von Xmx für die beste Leistung)
• mit einer Größe von Young Generation (Verhältnis 1, 2, 3) gebastelt
• PermGeneration erhöht
• versucht, verschiedene GC-Varianten

Hier sind einige Teile des gc-Protokoll. Sie können deutlich sehen, dass die GC-Dauer im Laufe der Zeit zunimmt und bei ca. 17 Sekunden liegt !!!

Was könnte diese Probleme verursachen? Gibt es irgendwelche JVM-Argumente, an denen man basteln könnte?

Update/25.03.2016

Nach VisualVM immer lief es mir eine/das Problem gefunden scheint: Young Generation jetzt auf 4 GB eingestellt ist - das Verhältnis zwischen Eden und Survivor scheint weg zu sein. .. Eden = 3,5 GB während Survivor = 0,5 GB Da es ständig neue Objekte gibt (eine Sache, die ich weiter untersuchen muss), wird Eden mit mehr als 0,5 GB bestückt (mehr wie 1 bis 2 GB). Der Überlebende kann es nicht halten und deshalb wird ein Major GC ausgelöst.

Neue Fragen, die sich:

1. falsch sind meine assumptiums?
2. Ich denke, meine nächsten Schritte sollten sein, das Überlebensverhältnis manuell einzustellen. Irgendwelche Vorschläge basierend auf meinem Fall?
3. Muss ich AdaptiveSizePolicy deaktivieren? (-XX: -UseAdaptiveSizePolicy)
4. Warum zeigt das GC-Protokoll die Ursache als "System.gc()“, während es definitiv keine manuelle GC ausgelöst in Code (alle Klassen dekompilierten und markiert):

2016-03-25T04:59:55.726+0100: 14992.418: [Full GC (System.gc())2016-03-25T04:59:55.726+0100: 14992.418: [CMS: 265708K->265749K(6291456K), 1.1520720 secs] 507160K->265749K(10066368K), [CMS Perm : 54875K->54875K(91504K)], 1.1523255 secs] [Times: user=1.14 sys=0.00, real=1.14 secs]

Old Logs/24.03.2016

ersten Protokolle nach dem Start :

12.434: [GC12.434: [ParNew: 1677824K->100069K(1887488K), 0.0983359 secs] 1677824K->100069K(10276096K), 0.0985257 secs] [Times: user=0.31 sys=0.02, real=0.11 secs] 
16.293: [GC16.293: [ParNew: 1777893K->209664K(1887488K), 0.1933143 secs] 1777893K->212290K(10276096K), 0.1934443 secs] [Times: user=0.50 sys=0.02, real=0.19 secs] 
19.994: [Full GC19.994: [CMS: 2626K->172662K(8388608K), 0.6312313 secs] 1521173K->172662K(10276096K), [CMS Perm : 24831K->24825K(24896K)], 0.6314259 secs] [Times: user=0.70 sys=0.06, real=0.64 secs] 
261.411: [Full GC261.411: [CMS: 172662K->27686K(8388608K), 0.2232379 secs] 876118K->27686K(10276096K), [CMS Perm : 30913K->30911K(41376K)], 0.2234464 secs] [Times: user=0.22 sys=0.00, real=0.22 secs] 
441.716: [Full GC441.716: [CMS: 27686K->24604K(8388608K), 0.1768511 secs] 500368K->24604K(10276096K), [CMS Perm : 30937K->30936K(51520K)], 0.1770344 secs] [Times: user=0.17 sys=0.00, real=0.17 secs] 

Einige Zeit später:

20235.044: [Full GC20235.044: [CMS: 195484K->248016K(8388608K), 1.0221468 secs] 798601K->248016K(10276096K), [CMS Perm : 52564K->52564K(87480K)], 1.0223571 secs] [Times: user=1.00 sys=0.02, real=1.01 secs] 
20431.860: [Full GC20431.860: [CMS: 248016K->404539K(8388608K), 1.6120188 secs] 1385622K->404539K(10276096K), [CMS Perm : 54537K->54536K(87672K)], 1.6122663 secs] [Times: user=1.58 sys=0.03, real=1.61 secs] 
20655.867: [Full GC20655.867: [CMS: 404539K->323692K(8388608K), 1.4389098 secs] 958490K->323692K(10276096K), [CMS Perm : 54655K->54652K(90896K)], 1.4391006 secs] [Times: user=1.43 sys=0.00, real=1.43 secs] 
20956.441: [Full GC20956.441: [CMS: 323692K->378663K(8388608K), 1.4717112 secs] 1233969K->378663K(10276096K), [CMS Perm : 54713K->54713K(91092K)], 1.4719180 secs] [Times: user=1.47 sys=0.00, real=1.47 secs] 
21149.053: [Full GC21149.053: [CMS: 378663K->284427K(8388608K), 1.1860728 secs] 717555K->284427K(10276096K), [CMS Perm : 54828K->54828K(91284K)], 1.1862890 secs] [Times: user=1.19 sys=0.00, real=1.19 secs] 
21438.332: [Full GC21438.332: [CMS: 284427K->519857K(8388608K), 2.0659280 secs] 1676708K->519857K(10276096K), [CMS Perm : 62993K->62984K(91476K)], 2.0662088 secs] [Times: user=2.03 sys=0.03, real=2.06 secs] 
21738.902: [Full GC21738.903: [CMS: 519857K->470206K(8388608K), 1.9628709 secs] 1590878K->470206K(10276096K), [CMS Perm : 63230K->63229K(104976K)], 1.9631042 secs] [Times: user=1.95 sys=0.00, real=1.95 secs] 
21922.221: [Full GC21922.221: [CMS: 470206K->448817K(8388608K), 1.7216487 secs] 1127397K->448817K(10276096K), [CMS Perm : 63269K->63269K(105384K)], 1.7218965 secs] [Times: user=1.72 sys=0.00, real=1.72 secs] 
22161.837: [Full GC22161.837: [CMS: 448817K->435548K(8388608K), 1.7168703 secs] 943145K->435548K(10276096K), [CMS Perm : 63298K->63298K(105576K)], 1.7170921 secs] [Times: user=1.72 sys=0.00, real=1.72 secs] 
22402.100: [Full GC22402.100: [CMS: 435548K->613005K(8388608K), 2.3503697 secs] 1841133K->613005K(10276096K), [CMS Perm : 65977K->65976K(105576K)], 2.3506446 secs] [Times: user=2.29 sys=0.05, real=2.34 secs] 
22642.893: [Full GC22642.893: [CMS: 613005K->621214K(8388608K), 2.3825301 secs] 1710749K->621214K(10276096K), [CMS Perm : 66925K->66924K(109964K)], 2.3827835 secs] [Times: user=2.37 sys=0.00, real=2.37 secs] 
22883.148: [Full GC22883.148: [CMS: 621214K->600821K(8388608K), 2.4086658 secs] 1523224K->600821K(10276096K), [CMS Perm : 67550K->67550K(111544K)], 2.4089147 secs] [Times: user=2.40 sys=0.00, real=2.40 secs] 

Auf dem Höhepunkt gc Dauer:

51603.282: [Full GC51603.282: [CMS: 4940385K->4859068K(8388608K), 16.6679541 secs] 5987385K->4859068K(10276096K), [CMS Perm : 114750K->114750K(153600K)], 16.6684484 secs] [Times: user=16.66 sys=0.00, real=16.66 secs] 
51813.482: [Full GC51813.482: [CMS: 4859068K->4900085K(8388608K), 16.4928686 secs] 6116576K->4900085K(10276096K), [CMS Perm : 114750K->114750K(153600K)], 16.4933047 secs] [Times: user=16.49 sys=0.00, real=16.49 secs] 
52026.148: [Full GC52026.148: [CMS: 4900085K->4896483K(8388608K), 16.8907197 secs] 6090675K->4896483K(10276096K), [CMS Perm : 114755K->114755K(153600K)], 16.8911947 secs] [Times: user=16.88 sys=0.00, real=16.89 secs] 
52223.160: [Full GC52223.160: [CMS: 4896483K->5031826K(8388608K), 17.1507980 secs] 6559062K->5031826K(10276096K), [CMS Perm : 114763K->114763K(153600K)], 17.1513112 secs] [Times: user=17.16 sys=0.00, real=17.16 secs] 
52425.802: [Full GC52425.802: [CMS: 5031826K->5016422K(8388608K), 17.8492606 secs] 6444936K->5016422K(10276096K), [CMS Perm : 114811K->114811K(153600K)], 17.8497294 secs] [Times: user=17.85 sys=0.00, real=17.85 secs] 
52628.857: [Full GC52628.858: [CMS: 5016422K->5077701K(8388608K), 17.9003775 secs] 6606932K->5077701K(10276096K), [CMS Perm : 114812K->114812K(153600K)], 17.9027559 secs] [Times: user=17.88 sys=0.02, real=17.89 secs] 
52747.442: [GC52747.443: [ParNew: 1677824K->209664K(1887488K), 1.3771078 secs] 6755525K->5530527K(10350324K), 1.3774630 secs] [Times: user=1.64 sys=0.08, real=1.37 secs] 
52833.644: [Full GC52833.644: [CMS: 5320863K->4956574K(8462836K), 17.7157636 secs] 6575478K->4956574K(10350324K), [CMS Perm : 114826K->114826K(153600K)], 17.7162266 secs] [Times: user=17.74 sys=0.00, real=17.72 secs] 
53058.481: [Full GC53058.482: [CMS: 4956574K->5002967K(8462836K), 17.9367047 secs] 6626713K->5002967K(10350324K), [CMS Perm : 114835K->114835K(153600K)], 17.9371138 secs] [Times: user=17.92 sys=0.00, real=17.92 secs] 

Voll Log: http://pastebin.ca/3409912

Answer 1

Ein Speicherleck, dass Pausen verursachen könnte. Wenn das System warmgelaufen ist, können Sie einen Snapshot eines Heaps (Heap Dump) erstellen und mit einem Tool wie Eclipse Memory Analyzer analysieren. Sie können den laufenden Prozess mit jvisualvm verbinden und versuchen, die Speichernutzung zu analysieren. Am effizientesten ist es, den Algorithmus zu optimieren.

Answer 2

Was könnte diese Probleme verursachen?

Fügen Sie -XX:+PrintGCCause hinzu, um zu sehen, was den vollständigen GC auslöst.

Answer 3

Wenn CMS fehlschlägt, fällt es zurück auf einen einzelnen Thread-Collector (Sie können dies durch die Real == Benutzerzeit sehen) Dies möchten Sie vermeiden.

Ich vermute, dass deine Survivor-Felder nicht groß genug sind, sodass, wenn der Eden-Raum aufgeräumt ist, nicht genug Platz in den Überlebenden ist und dies einen vollständigen GC auslöst, single threaded.