Я сподіваюся, що це питання дуже схоже на: висока кількість-cms-mark / замітка-пауза-навіть-хоча-старий-gen-is-не-наполовину і tenured-collection-begin-for-no-visible-reason. Я відправляю, тому що 1. ці потоки перевищують 1 рік, і 2. Я сподіваюся дізнатися, як знайти корінні причини для початку такої поведінки.
У нас є OAS / OC4J (це не наша вина!) 24/7 працює додаток Java-додатківRHEL5 / Redhat 5.11, Java 6. Це було стабільною пам'яттю протягом багатьох років до недавнього часу, коли ми почали бачити високу завантаженість процесора через часті космічні цикли CMS. Це відбувається навіть тоді, коли є більше, ніж достатньо простору в обох молодих і зайнятих місцях. Моє читання на цю тему говорить про те, що циклічний цикл CMS зазвичай починається тоді, коли простір (Old gen) становить приблизно 92% потенціалу. що відбувається з 30% потужністю ще менше., а також, я повинен згадати, коли загальна кількість здається меншою, ніж значення за замовчуванням 45% для загального використання купою, ака InitiatingHeapOccupancyPercent.
Ми все ще переглядаємо останні зміни коду таспробували кілька речей, але ці проблеми зберігаються. Отже, ми не можемо відтворити за межами виробничих серверів, хоча зусилля в середовищі dev / qa тривають.
Я думаю, що тут є три основні питання:
- Що може викликати часте (передчасне?) Фаза початкового позначення циклу CMS. І як ми можемо перевірити чи дослідити це? Наприклад, перевірте різні сегменти поточного розподілу пам'яті (eden, survivor, old-gen) для величезних об'єктів або подібного?
- Я читав про використання
-XX:+UseCMSInitiatingOccupancyOnlyі-XX:CMSInitiatingOccupancyFraction=NN(наприклад, у згаданих вище статтях). Що може бути розумним (== безпечним) значенням для NN, і які ризики перевизначення ергономіки CMS за замовчуванням таким чином? - Інші речі, які ми повинні розглянути чи дослідити?
Ось деякі відомості про нашу проблему:
- Отже, ми не можемо відтворити це поза виробництвом. Отже, налагодження або налаштування не є опцією
- Ми використовуємо нічну роботу cron, щоб змусити Full GC пом'якшити фрагментацію через jmap -histo: live ПІД</ strong>
- Пам'ять аргументів командного рядка JVM нижче:
-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
Примітка: ми нещодавно спробували підняти молоде покоління до 3,5 г як дещо відчайдушний експеримент. (У виробництві!) Ніяких реальних помітних відмінностей не спостерігається
- Вихідні дані
jmap -heap. Примітка:From Spaceздається, завжди зайнятий на 100%. Чи є це нормально, або вказує на що-небудь ?:
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>
- Вихідний сигнал з внутрішнього парсера GC Log, що показуєчасті початкові цикли (IM) / зауваження (RM), а також низька зайнятість молодої людини. Ви можете бачити, що зайнятість молодого покоління повільно зростає до 98,30%, після чого ми робимо очікуване
ParNew(PN) Young 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]...
- Фактичний вихідний журнал GC, починаючи з першої початкової позначки (IM) у
14:17:03.057з виходу вище. Аналогічним чином, як показано вище, але я показую ParNew Young GC для повноти:
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]
Перехід від великого спостереження Олексія іпропозиції, ми намагатимемося зіштовхнутися з Perm Generation у виробництві (і я доповідаю). Але, як попереднє підтвердження його здогадки, я зробив огляд використання покоління гена для всіх контейнерів JVM на одному з наших хостів, і здається дуже правдоподібним. У наведеному нижче фрагменті PID = 2979 (на 92% потенціалу дозволу гена) є тим, що демонструє постійні набори CMS-колекції.
[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
Відповіді:
0 для відповіді № 1CMS старий цикл очищення простору він запускається, коли старий простір досягає порогу заповнення або постійний простір досягає порогу.
До Java 8 постійний простір є частиною зібраного сміття і в межах алгоритму CMS.
У вашому випадку перм на рівні 93%
Perm Generation:
capacity = 268435456 (256.0MB)
used = 249858712 (238.2838363647461MB)
free = 18576744 (17.716163635253906MB)
93.07962357997894% used
Ця стаття описує подібний випадок.
Якщо б раджу збільшити пропускну здатність простір або ви можете налаштувати окремий поріг заповнення проміжного простору за допомогою –XX: CMSInitiatingPermOccupancyFraction=95 варіант
Додаткові параметри налаштування GC.