Ich erkenne von vornherein an, dass dieses Problem sehr ähnlich ist zu: hohe Anzahl von cm-Markierungen / Bemerkungspausen - obwohl - obwohl das alte Gen nicht halb voll ist und Tenured-Sammlung-Starten-für-kein-scheinbaren-Grund. Ich poste, weil 1. diese Threads älter als 1 Jahr sind, und 2. ich hoffe zu lernen, wie man die Ursachen für den Beginn dieses Verhaltens findet.
Wir haben eine OAS / OC4J (es ist nicht unsere Schuld!) Java-Anwendungsserver läuft rund um die UhrRHEL5 / Redhat 5.11, Java 6. Dies ist seit vielen Jahren im Hinblick auf den Speicher stabil, bis wir vor kurzem eine hohe CPU-Auslastung durch häufige CMS-Dauerzyklen bemerken. Dies geschieht auch dann, wenn in jungen und dauerhaften Räumen mehr als genug Platz zur Verfügung steht. Meine Lektüre dieses Themas legt nahe, dass ein CMS-Dauerzyklus in der Regel beginnt, wenn der dauerhafte Platz (Old Gen) etwa 92% der Kapazität beträgt. Dies wird jedoch immer wieder angezeigt mit 30% Kapazität sogar noch weniger und außerdem sollte ich erwähnen, dass der Gesamtheap weniger als der Standardwert von 45% für die Gesamtheap-Nutzung, aka InitiatingHeapOccupancyPercent.
Wir überprüfen immer noch die letzten Codeänderungen undhabe ein paar Dinge ausprobiert, aber diese Probleme bestehen fort. Bisher ist es uns nicht möglich, außerhalb von Produktionsservern zu reproduzieren, obwohl die Bemühungen in einer dev / qa-Umgebung andauern.
Ich denke, ich habe hier drei Hauptfragen:
- Was könnte das Häufige auslösen (verfrüht?) Initial-Mark-Phase des CMS-Zyklus. Und wie können wir das überprüfen oder untersuchen? ZB verschiedene Segmente der aktuellen Speicherzuordnung (Eden, Überlebender, Alte) auf große Objekte oder ähnliches untersuchen?
- Ich habe über die Verwendung gelesen
-XX:+UseCMSInitiatingOccupancyOnlyund-XX:CMSInitiatingOccupancyFraction=NN(zum Beispiel in Artikeln, auf die oben verwiesen wurde). Was könnte ein vernünftiger (= sicherer) Wert sein für NN, und welche Risiken bestehen darin, die Standard-Ergonomie von CMS auf diese Weise zu überschreiben? - Irgendwelche anderen Dinge, die wir berücksichtigen oder untersuchen sollten?
Hier sind einige Details zu unserem Problem:
- Bislang ist es uns nicht möglich, dies außerhalb der Produktion zu reproduzieren. Debugging oder Tuning ist also keine Option
- Wir verwenden einen nächtlichen Cron-Job, um eine vollständige GC zu erzwingen, um die Fragmentierung über zu mildern jmap -histo: leben pid</ strong>
- Nachfolgend finden Sie unsere JVM-Befehlszeilen-Befehlszeilen.
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintTenuringDistribution
-XX:-TraceClassUnloading
-XX:+UseConcMarkSweepGC
-XX:+CMSClassUnloadingEnabled
-XX:+HeapDumpOnOutOfMemoryError
-XX:+ExplicitGCInvokesConcurrent
-XX:+UseCMSCompactAtFullCollection
-Xms10g
-Xmx10g
-Xmn3g
-XX:SurvivorRatio=6
-XX:PermSize=256m
-XX:MaxPermSize=256m
-XX:TargetSurvivorRatio=80
-XX:ParallelGCThreads=8
Anmerkung: Wir haben vor kurzem versucht, die junge Generation auf 3,5 g zu heben, als etwas verzweifeltes Experiment. (In Produktion!) Es sind keine echten Unterschiede festzustellen
- Ausgabe von
jmap -heap. Hinweis:From Spacescheint immer zu 100% besetzt zu sein. Ist das normal oder deutet auf irgendetwas hin ?:
using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC
Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 10737418240 (10240.0MB)
NewSize = 3758096384 (3584.0MB)
MaxNewSize = 3758096384 (3584.0MB)
OldSize = 5439488 (5.1875MB)
NewRatio = 2
SurvivorRatio = 6
PermSize = 268435456 (256.0MB)
MaxPermSize = 268435456 (256.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 3288334336 (3136.0MB)
used = 1048575408 (999.9994354248047MB)
free = 2239758928 (2136.0005645751953MB)
31.88773709900525% used
Eden Space:
capacity = 2818572288 (2688.0MB)
used = 578813360 (551.9994354248047MB)
free = 2239758928 (2136.0005645751953MB)
20.535693282172794% used
From Space:
capacity = 469762048 (448.0MB)
used = 469762048 (448.0MB)
free = 0 (0.0MB)
100.0% used
To Space:
capacity = 469762048 (448.0MB)
used = 0 (0.0MB)
free = 469762048 (448.0MB)
0.0% used
concurrent mark-sweep generation:
capacity = 6979321856 (6656.0MB)
used = 1592989856 (1519.1935119628906MB)
free = 5386332000 (5136.806488037109MB)
22.82442175425016% used
Perm Generation:
capacity = 268435456 (256.0MB)
used = 249858712 (238.2838363647461MB)
free = 18576744 (17.716163635253906MB)
93.07962357997894% used
</ pre></ code>
- Ausgabe eines internen GC-Log-Parsers, angezeigthäufige Anfangsnoten (IM) / Kommentar (RM) und geringe Belegung junger / fester Mitarbeiter. Sie können sehen, dass die Auslastung der jungen Gene langsam auf 98,30% ansteigt, und bald tun wir die erwarteten
ParNew(PN) junge GC:
| | PN: |YHeapB4|YHeapAf|YHeapDt|
| |------|-------|-------|-------|
| |PF,CF,| | | |
| | SY: |OHeapB4|OHeapAf|OHeapDt|
| |------|-------|-------|-------|
Date |Time |IM,RM:|Y Occ% |OHeap |O Occ% |Duration|THeapB4|THeapAf|THeapDt|Promoted|% Garbage|Interval| Alloc |AllocRate(MB/s)|PromoRate(MB/s)
------------------------------------------------------------------------------------------------------------------------------------------------------------
2016-12-05|14:16:59.455| RM | 15.11|1620287| 23.77| 0.18
2016-12-05|14:17:03.057| IM | 16.16|1615358| 23.70| 0.66
2016-12-05|14:17:13.444| RM | 17.70|1615358| 23.70| 0.23
2016-12-05|14:17:17.227| IM | 18.82|1513691| 22.21| 0.70
2016-12-05|14:17:27.887| RM | 28.54|1513691| 22.21| 0.33
2016-12-05|14:17:30.390| IM | 29.45|1513667| 22.21| 1.02
2016-12-05|14:17:41.326| RM | 32.90|1513667| 22.21| 0.66
2016-12-05|14:17:44.290| IM | 34.86|1513666| 22.21| 1.23
...[deleted for brevity]...
2016-12-05|14:37:28.024| IM | 95.88|1377444| 20.21| 2.93
2016-12-05|14:37:40.601| RM | 95.89|1377444| 20.21| 2.15
2016-12-05|14:37:46.032| IM | 95.89|1377443| 20.21| 2.83
2016-12-05|14:37:58.557| RM | 98.30|1377443| 20.21| 2.21
2016-12-05|14:38:03.988| IM | 98.30|1377307| 20.21| 2.90
2016-12-05|14:38:15.638| PN |3211264| 458752|2752512| 0.77|4588571|1942900|2645671| 106841| 96.12
2016-12-05|14:38:18.193| RM | 18.04|1484148| 21.78| 0.24
2016-12-05|14:38:21.813| IM | 18.04|1480802| 21.73| 0.75
2016-12-05|14:38:31.822| RM | 19.05|1480802| 21.73| 0.34
...[and so on]...
- Aktuelle GC-Protokollausgabe beginnend mit der ersten Initial Mark (IM) um
14:17:03.057von oben Ausgabe. Ähnlich wie oben abgeschnitten, aber ich zeige den ParNew Young GC zur Vollständigkeit:
2016-12-05T14:17:03.057-0800: [GC [1 CMS-initial-mark: 1615358K(6815744K)] 2134211K(10027008K), 0.6538170 secs] [Times: user=0.65 sys=0.00, real=0.66 secs]
2016-12-05T14:17:06.178-0800: [CMS-concurrent-mark: 2.463/2.467 secs] [Times: user=5.04 sys=0.01, real=2.46 secs]
2016-12-05T14:17:06.251-0800: [CMS-concurrent-preclean: 0.072/0.073 secs] [Times: user=0.07 sys=0.00, real=0.08 secs]
CMS: abort preclean due to time 2016-12-05T14:17:13.442-0800: [CMS-concurrent-abortable-preclean: 7.189/7.192 secs] [Times: user=7.46 sys=0.02, real=7.19 secs]
2016-12-05T14:17:13.444-0800: [GC[YG occupancy: 568459 K (3211264 K)][Rescan (parallel) , 0.1020240 secs][weak refs processing, 0.0312140 secs][class unloading, 0.0396040 secs][scrub symbol & string tables, 0.0368990 secs] [1 CMS-remark: 1615358K(6815744K)] 2183818K(10027008K), 0.2344980 secs] [Times: user=0.89 sys=0.00, real=0.23 secs]
2016-12-05T14:17:15.212-0800: [CMS-concurrent-sweep: 1.533/1.533 secs] [Times: user=1.54 sys=0.00, real=1.54 secs]
2016-12-05T14:17:15.225-0800: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-12-05T14:17:17.227-0800: [GC [1 CMS-initial-mark: 1513691K(6815744K)] 2118034K(10027008K), 0.7036950 secs] [Times: user=0.71 sys=0.00, real=0.70 secs]
2016-12-05T14:17:20.548-0800: [CMS-concurrent-mark: 2.613/2.617 secs] [Times: user=5.62 sys=0.03, real=2.62 secs]
2016-12-05T14:17:20.667-0800: [CMS-concurrent-preclean: 0.113/0.119 secs] [Times: user=0.23 sys=0.00, real=0.12 secs]
CMS: abort preclean due to time 2016-12-05T14:17:27.886-0800: [CMS-concurrent-abortable-preclean: 7.217/7.219 secs] [Times: user=8.54 sys=0.07, real=7.22 secs]
2016-12-05T14:17:27.887-0800: [GC[YG occupancy: 916526 K (3211264 K)][Rescan (parallel) , 0.2159770 secs][weak refs processing, 0.0000180 secs][class unloading, 0.0460640 secs][scrub symbol & string tables, 0.0404060 secs] [1 CMS-remark: 1513691K(6815744K)] 2430218K(10027008K), 0.3276590 secs] [Times: user=1.59 sys=0.02, real=0.33 secs]
2016-12-05T14:17:29.611-0800: [CMS-concurrent-sweep: 1.396/1.396 secs] [Times: user=1.40 sys=0.00, real=1.39 secs]
...[And So On]...
2016-12-05T14:38:03.988-0800: [GC [1 CMS-initial-mark: 1377307K(6815744K)] 4534072K(10027008K), 2.9013180 secs] [Times: user=2.90 sys=0.00, real=2.90 secs]
2016-12-05T14:38:09.403-0800: [CMS-concurrent-mark: 2.507/2.514 secs] [Times: user=5.03 sys=0.03, real=2.51 secs]
2016-12-05T14:38:09.462-0800: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
2016-12-05T14:38:15.638-0800: [GC [ParNew
Desired survivor size 375809632 bytes, new threshold 4 (max 15)
- age 1: 115976192 bytes, 115976192 total
- age 2: 104282224 bytes, 220258416 total
- age 3: 85871464 bytes, 306129880 total
- age 4: 98122648 bytes, 404252528 total
: 3211264K->458752K(3211264K), 0.7731320 secs] 4588571K->1942900K(10027008K), 0.7732860 secs] [Times: user=3.15 sys=0.00, real=0.77 secs]
CMS: abort preclean due to time 2016-12-05T14:38:18.192-0800: [CMS-concurrent-abortable-preclean: 7.842/8.730 secs] [Times: user=12.50 sys=0.07, real=8.73 secs]
2016-12-05T14:38:18.193-0800: [GC[YG occupancy: 579220 K (3211264 K)][Rescan (parallel) , 0.1208810 secs][weak refs processing, 0.0008320 secs][class unloading, 0.0483220 secs][scrub symbol & string tables, 0.0414970 secs] [1 CMS-remark: 1484148K(6815744K)] 2063368K(10027008K), 0.2376050 secs] [Times: user=1.07 sys=0.00, real=0.24 secs]
2016-12-05T14:38:19.798-0800: [CMS-concurrent-sweep: 1.366/1.366 secs] [Times: user=1.40 sys=0.00, real=1.37 secs]
2016-12-05T14:38:19.811-0800: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-12-05T14:38:21.813-0800: [GC [1 CMS-initial-mark: 1480802K(6815744K)] 2060239K(10027008K), 0.7487000 secs] [Times: user=0.75 sys=0.00, real=0.75 secs]
Geht von Alexey 's großartiger Beobachtung undAnregungen, wir werden versuchen, Perm Generation in der Produktion zu stoßen (und ich melde mich zurück). Als vorläufige Bestätigung seiner Vermutung habe ich eine Umfrage zur Dauergeneration aller Container-JVMs auf einem unserer Hosts durchgeführt und scheint sehr plausibel. In dem nachstehenden Ausschnitt ist PID = 2979 (bei 92% Perm-Kapazität) derjenige, der das konstante CMS-Sammelverhalten zeigt.
[oracle@ikm-oasb-3 bin]$ for p in `opmnctl status | grep OC4JG | awk "{print $5}"`; do echo -n "PID=$p "; jmap -heap $p | grep -A4 "Perm Gen" | egrep "%"; done 2> /dev/null
PID=8456 89.31778371334076% used
PID=8455 89.03931379318237% used
PID=8454 91.1630779504776% used
PID=8453 89.17466700077057% used
PID=8452 87.69496977329254% used
PID=2979 92.2750473022461% used
PID=1884 90.25585949420929% used
PID=785 76.16643011569977% used
PID=607 89.06879723072052% used
Antworten:
0 für die Antwort № 1Der alte CMS-Bereinigungszyklus wird ausgelöst, wenn der alte oder der permanente Platz den Schwellenwert erreicht.
Vor Java 8 ist der permanente Speicherplatz ein Teil des Müllsammelhaufens und des CMS-Algorithmus.
In Ihrem Fall ist die Dauerwelle bei 93%
Perm Generation:
capacity = 268435456 (256.0MB)
used = 249858712 (238.2838363647461MB)
free = 18576744 (17.716163635253906MB)
93.07962357997894% used
Dieser Artikel beschreibt einen ähnlichen Fall.
Wenn Sie sich empfehlen, den Perm-Speicherplatz zu vergrößern, können Sie einen separaten Belegungsschwellenwert für den Perm-Speicherbereich konfigurieren –XX: CMSInitiatingPermOccupancyFraction=95 Möglichkeit.