Help, ramki_at_jdc!!! Sudden jump in heap and 2 GC threads ate most cpu...
JDK 1.4.2_12
HW: Sun V240 2X 1GHz cpu + 8GMem
MEM_ARGS=" -Xms1500m -Xmx1500m -XX:PermSize=270m -XX:MaxPermSize=300m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC \
-XX:+PrintCompilation \
-XX:+CMSParallelRemarkEnabled -XX:ParallelGCThreads=2 -XX:NewSize=64M -XX:MaxNewSize=64M -XX:SurvivorRatio=4 \
-verbose:gc -Xloggc:${GC_LOG} -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC "
OldGen grew 170M in a few sec. There is NO logic in apps to do that:
28300.555: [ParNew: 48563K->5393K(54656K), 5.2490298 secs] 851156K->807986K(1525120K) Heap after GC invocations=1552:
Heap
par new generationtotal 54656K, used 5393K [0x89000000, 0x8d000000, 0x8d000000)
eden space 43776K,0% used [0x89000000, 0x89000000, 0x8bac0000)
from space 10880K, 49% used [0x8bac0000, 0x8c004720, 0x8c560000)
tospace 10880K,0% used [0x8c560000, 0x8c560000, 0x8d000000)
concurrent mark-sweep generation total 1470464K, used 802593K [0x8d000000, 0xe6c00000, 0xe6c00000)
concurrent-mark-sweep perm gen total 307200K, used 290377K [0xe6c00000, 0xf9800000, 0xf9800000)
} , 5.2494367 secs]
28306.160: [CMS-concurrent-sweep: 4.609/14.326 secs]
28306.161: [CMS-concurrent-reset-start]
28306.369: [CMS-concurrent-reset: 0.208/0.208 secs]
28311.064: [GC {Heap before GC invocations=1552:
Heap
par new generationtotal 54656K, used 49169K [0x89000000, 0x8d000000, 0x8d000000)
eden space 43776K, 100% used [0x89000000, 0x8bac0000, 0x8bac0000)
from space 10880K, 49% used [0x8bac0000, 0x8c004720, 0x8c560000)
tospace 10880K,0% used [0x8c560000, 0x8c560000, 0x8d000000)
concurrent mark-sweep generation total 1470464K, used 974460K [0x8d000000, 0xe6c00000, 0xe6c00000)
concurrent-mark-sweep perm gen total 307200K, used 290379K [0xe6c00000, 0xf9800000, 0xf9800000)
28311.064: [ParNew: 49169K->6973K(54656K), 10.8971482 secs] 1023630K->981434K(1525120K) Heap after GC invocations=1553:
Heap
par new generationtotal 54656K, used 6973K [0x89000000, 0x8d000000, 0x8d000000)
eden space 43776K,0% used [0x89000000, 0x89000000, 0x8bac0000)
from space 10880K, 64% used [0x8c560000, 0x8cc2f5d8, 0x8d000000)
tospace 10880K,0% used [0x8bac0000, 0x8bac0000, 0x8c560000)
concurrent mark-sweep generation total 1470464K, used 974460K [0x8d000000, 0xe6c00000, 0xe6c00000)
concurrent-mark-sweep perm gen total 307200K, used 290379K [0xe6c00000, 0xf9800000, 0xf9800000)
} , 10.8975315 secs]
Two threads of CMS ate most of cpu in the meantime:
PID: 23275
result : 24% java/2
24% java/3
lwp# 2 / thread# 2 --
fef3ad9c __1cYCardTableModRefBSForCTRSUcard_will_be_scanned6MW_i_ (a43a0, b5ee8, 13d0978, 1826, fe27f900, 1a84cb0) + 10
fef3a7cc __1cRCardTableModRefBSOprocess_stride6MpnFSpace_nJMemRegion_iipnVDirtyCardToOopClosure_pnQMemRegionClosure_ippWII_v_ (1a84cb0, 0, fe27fa78, 400, bd4c0000, 8000) + 154
fef39e1c __1cRCardTableModRefBSbFpar_non_clean_card_iterate_work6MpnFSpace_nJMemRegion_pnVDirtyCardToOopClosure_pnQMemRegionClosure_ii_v_ (0, b5ee8, fe27fa08, 13d0978, fe27fa78, 0) + b0
fee29628 __1cRCardTableModRefBSWnon_clean_card_iterate6MpnFSpace_nJMemRegion_pnVDirtyCardToOopClosure_pnQMemRegionClosure_i_v_ (a43a0, b5ee8, fe27fa70, 13d0978, fe27fa78, 0) + 74
fee29518 __1cLCardTableRSbDyounger_refs_in_space_iterate6MpnFSpace_pnQOopsInGenClosure__v_ (a4398, b5ee8, fe27fc28, a4398, d, b5dc8) + 98
fef73840 __1cbDConcurrentMarkSweepGenerationUyounger_refs_iterate6MpnQOopsInGenClosure__v_ (b5dc8, fe27fc28, fe27fc28, 0, 0, 0) + 50
fee27920 __1cQGenCollectedHeapUprocess_strong_roots6Miiin0ATClassScanningOption_pnQOopsInGenClosure_3_v_ (ff1aa000, fe27fc4c, ff201d08, 0, 1, fe27fc28) + 310
ff0c32f8 __1cNParNewGenTaskEwork6Mi_v_ (f9a7fa88, 1, 0, 4400, 46a4, 0) + 3d8
ff121b8c __1cKGangWorkerDrun6M_v_ (a3078, 2, 40, 0, 40, 0) + ac
ff0b8614 java_start (a3078, 0, 0, 0, 0, 0) + 134
ff3857b4 _lwp_start (0, 0, 0, 0, 0, 0)
-- lwp# 3 / thread# 3 --
fef3aa9c __1cRCardTableModRefBSYprocess_chunk_boundaries6MpnFSpace_pnVDirtyCardToOopClosure_nJMemRegion_5ppWII_v_ (a43a0, b5ee8, 3e4f50, 1847, fc77f900, 1a84cb0) + 298
fef3a7cc __1cRCardTableModRefBSOprocess_stride6MpnFSpace_nJMemRegion_iipnVDirtyCardToOopClosure_pnQMemRegionClosure_ippWII_v_ (1a84cb0, 0, fc77fa78, 400, bd8e0000, 8000) + 154
fef39e1c __1cRCardTableModRefBSbFpar_non_clean_card_iterate_work6MpnFSpace_nJMemRegion_pnVDirtyCardToOopClosure_pnQMemRegionClosure_ii_v_ (0, b5ee8, fc77fa08, 3e4f50, fc77fa78, 0) + b0
fee29628 __1cRCardTableModRefBSWnon_clean_card_iterate6MpnFSpace_nJMemRegion_pnVDirtyCardToOopClosure_pnQMemRegionClosure_i_v_ (a43a0, b5ee8, fc77fa70, 3e4f50, fc77fa78, 0) + 74
fee29518 __1cLCardTableRSbDyounger_refs_in_space_iterate6MpnFSpace_pnQOopsInGenClosure__v_ (a4398, b5ee8, fc77fc28, a4398, d, b5dc8) + 98
fef73840 __1cbDConcurrentMarkSweepGenerationUyounger_refs_iterate6MpnQOopsInGenClosure__v_ (b5dc8, fc77fc28, fc77fc28, 0, 0, 0) + 50
fee27920 __1cQGenCollectedHeapUprocess_strong_roots6Miiin0ATClassScanningOption_pnQOopsInGenClosure_3_v_ (ff1aa000, fc77fc4c, ff201d08, 0, 1, fc77fc28) + 310
ff0c32f8 __1cNParNewGenTaskEwork6Mi_v_ (f9a7fa88, 0, 0, 4400, 46a4, 1) + 3d8
ff121b8c __1cKGangWorkerDrun6M_v_ (a39f0, 3, 40, 0, 40, 0) + ac
ff0b8614 java_start (a39f0, 0, 0, 0, 0, 0) + 134
ff3857b4 _lwp_start (0, 0, 0, 0, 0, 0)
Not sure if this related to any known bug of GC. Thanks in advance.
