7回复
4年前
CMS collector没有按照CMSWaitDuration触发
背景
本打算验证一下CMSWaitDuration参数，但是发现CMS collector在CMSWaitDuration之前提前触发了。
jvm版本信息
jvm启动参数
java -verbose:gc -Xms20M -Xmx20M -Xmn5M -XX:+PrintGCDetails -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:Survi
vorRatio=8 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution -XX:+PrintHea
pAtGC -XX:+PrintGC -XX:+PrintCMSInitiationStatistics -XX:CMSWaitDuration=80000 -XX:+Verbose
测试程序
public static void main(String[] args) throws InterruptedException {
List<byte[]> list = new ArrayList<>(3);
list.add(new byte[12*1024*1024]);//大对象直接分配到老年代，老年代当前占用12m，剩余3m
Thread.sleep(3000);
list.add(new byte[1*1024*1024]);//分配到年轻代，年轻代当前占用1m+
Thread.sleep(2000);
list.add(new byte[3*1024*1024]);//年轻代gc，1m+内容晋升到老年代，现在年轻代占用3m+，老年代占用13m+
Thread.sleep(5000);
}
gc log
MarkStackSize: 4096k MarkStackSizeMax: 524288k
ConcGCThreads: 0
Minimum heap 20971520 Initial heap 20971520 Maximum heap 20971520
1: Minimum gen0 5242880 Initial gen0 5242880 Maximum gen0 5242880
Minimum gen1 15728640 Initial gen1 15728640 Maximum gen1 15728640
TwoGenerationCollectorPolicy::mem_allocate_work: attempting locked slow path allocation
DefNewGeneration::allocate_from_space(1572866): will_fail: false heap_lock: locked free: 524288 should_allocate_from_space: NOT
returns NULL
TwoGenerationCollectorPolicy::mem_allocate_work: attempting locked slow path allocation
DefNewGeneration::allocate_from_space(393218): will_fail: false heap_lock: locked free: 524288 should_allocate_from_space: NOT
returns NULL
{Heap before GC invocations=0 (full 0):
par new generation total 4608K, used 1891K [0x00000000fec00000, 0x00000000ff100000, 0x00000000ff100000)
eden space 4096K, 46% used [0x00000000fec00000, 0x00000000fedd8e18, 0x00000000ff000000)
from space 512K, 0% used [0x00000000ff000000, 0x00000000ff000000, 0x00000000ff080000)
to space 512K, 0% used [0x00000000ff080000, 0x00000000ff080000, 0x00000000ff100000)
concurrent mark-sweep generation total 15360K, used 12288K [0x00000000ff100000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 2914K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 276K, capacity 386K, committed 512K, reserved 1048576K
5.220: [GC (Allocation Failure) Allocated 1 objects, 12582928 bytes concurrently5.220: [ParNewlevel=0 invoke=1 size=3145744CMS: promo attempt is safe: available(3145712) >= av_promo(0),max_promo(1936920)
Desired survivor size 262144 bytes, new threshold 1 (max 15)
- age 1: 518968 bytes, 518968 total
: 1936920->523176(4718592), 0.0104102 secs] 14519848->14352088(20447232)Promoted 2611 objects, 1227120 bytes Contiguous available 1636768 bytes , 0.0106530 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
Heap after GC invocations=1 (full 0):
par new generation total 4608K, used 510K [0x00000000fec00000, 0x00000000ff100000, 0x00000000ff100000)
eden space 4096K, 0% used [0x00000000fec00000, 0x00000000fec00000, 0x00000000ff000000)
from space 512K, 99% used [0x00000000ff080000, 0x00000000ff0ffba8, 0x00000000ff100000)
to space 512K, 0% used [0x00000000ff000000, 0x00000000ff000000, 0x00000000ff080000)
concurrent mark-sweep generation total 15360K, used 13504K [0x00000000ff100000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 2914K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 276K, capacity 386K, committed 512K, reserved 1048576K
}
CMS: collect because of occupancy 0.879219 / 0.800000 CMS old gen initiated
5.231: [GC (CMS Initial Mark) 5.232: [
checkpointRootsInitialWork, 0.0015963 secs]
[1 CMS-initial-mark: 13828912(15728640)] 17497832(20447232), 0.0018602 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
5.233: [CMS-concurrent-mark-start]
5.239: [CMS-concurrent-mark: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
5.239: [CMS-concurrent-preclean-start]
(modUnionTable: 0 cards)5.239: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
5.239: [CMS-concurrent-abortable-preclean-start]
CMS: promo attempt is safe: available(1899728) >= av_promo(1245984),max_promo(3668920)
CMS: promo attempt is safe: available(1899728) >= av_promo(1245984),max_promo(3668920)
...N次相同的输出
CMS: promo attempt is safe: available(1899728) >= av_promo(1245984),max_promo(3668920)
(modUnionTable: 0 cards)Heap
par new generation total 4608K, used 3665K [0x00000000fec00000, 0x00000000ff100000, 0x00000000ff100000)
eden space 4096K, 77% used [0x00000000fec00000, 0x00000000fef14930, 0x00000000ff000000)
from space 512K, 99% used [0x00000000ff080000, 0x00000000ff0ffba8, 0x00000000ff100000)
to space 512K, 0% used [0x00000000ff000000, 0x00000000ff000000, 0x00000000ff080000)
concurrent mark-sweep generation total 15360K, used 13504K [0x00000000ff100000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 2921K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 277K, capacity 386K, committed 512K, reserved 1048576K
ClassLoaderData CLD: 0x000000001622a4b0, loader: 0x00000000ff080000, loader_klass: 0x000000010000f6a8 sun/misc/Launcher$AppClassLoader { claimed handles 0x0000000000000000
metaspace: 0x00000000162284b0
Virtual space manager: 0x0000000016225aa0
0) Metachunk: bottom 0x0000000015a20000 top 0x0000000015a204f8 end 0x0000000015a21000 size 512
used 159 free 353
total of all chunks 512 used 159 free 353 capacity 512 waste 6
Class space manager: 0x0000000016225fa0
0) Metachunk: bottom 0x0000000100060000 top 0x0000000100060220 end 0x0000000100060800 size 256
used 68 free 188
total of all chunks 256 used 68 free 188 capacity 256 waste 6
jni_method_id count = 1
}
ClassLoaderData CLD: 0x00000000034655d0, loader: 0x0000000000000000, loader_klass: 0x0000000000000000 <bootloader> { claimed handles 0x0000000016014180
metaspace: 0x00000000034cf190
Virtual space manager: 0x00000000034d9110
0) Metachunk: bottom 0x0000000015620000 top 0x00000000158b4d88 end 0x0000000015a20000 size 524288
used 338353 free 185935
total of all chunks 524288 used 338353 free 185935 capacity 524288 waste 6
Class space manager: 0x00000000034d91b0
0) Metachunk: bottom 0x0000000100000000 top 0x0000000100045218 end 0x0000000100060000 size 49152
used 35395 free 13757
total of all chunks 49152 used 35395 free 13757 capacity 49152 waste 6
jni_method_id count = 16
}
All Metaspace:
data space: Chunk accounting: used in chunks 2644K + unused in chunks 1455K + capacity in free chunks 0K = 4100K capacity in allocated chunks 4100K
class space: Chunk accounting: used in chunks 277K + unused in chunks 108K + capacity in free chunks 0K = 386K capacity in allocated chunks 386K
Total fragmentation waste (words) doesn't count free space
data: 0 specialized(s) 0, 1 small(s) 0, 0 medium(s) 0, large count 1
class: 0 specialized(s) 0, 1 small(s) 0, 0 medium(s) 0, large count 1
[Verifying Threads Heap concurrent mark-sweep generation CMS: promo attempt is safe: available(1899728) >= av_promo(1245984),max_promo(3753176)
par new generation remset SymbolTable StringTable CodeCache SystemDictionary ClassLoaderDataGraph MetaspaceAux JNIHandles C-heap CodeCache Oops ]
疑惑点
按照配置CMSWaitDuration=80000，CMS collector应该是8s触发一次才对，为什么在5.231s的时候就提前触发了呢？
4205 阅读
