RFR (XXS): 8164133: Tests gc/arguments/TestAlignmentToUseLargePages.java and gc/cms/TestBubbleUpRef.java use too small heap
Dmitry Fazunenko
dmitry.fazunenko at oracle.com
Mon Aug 22 15:55:33 UTC 2016
Jon,
The problem could be reproduced by the following command:
#> java -Xmx3m -XX:+UseConcMarkSweepGC -XX:+AggressiveOpts -version
Error occurred during initialization of VM
GC triggered before VM initialization completed. Try increasing NewSize,
current value 640K.
increasing Xmx from 3m to 4m helps:
#> java -Xmx4m -XX:+UseConcMarkSweepGC -XX:+AggressiveOpts -version
java version "9-ea"
Java(TM) SE Runtime Environment (build 9-ea+132)
Java HotSpot(TM) 64-Bit Server VM (build 9-ea+132, mixed mode)
I don't see anything suspicious in the GC log (attached).
There is no requirement to minimal heap required for Hotspot to work
normally, so I think the tests should not start VM with so small heaps.
Thanks,
Dima
On 19.08.2016 21:02, Jon Masamitsu wrote:
> Dima,
>
> The error message I see in the logs is
>
> GC triggered before VM initialization completed. Try increasing
> NewSize, current value 1280K.
>
> Do you know why the NewSize is so small? I ask because I'm
> not sure setting a larger heap size will always fix this failure.
>
> If the test is run (with the parameters that fail) and
> -Xlog:gc*=trace, you might
> see why the NewSize is so small (if you don't know now).
>
> Jon
>
>
> On 8/19/2016 9:02 AM, Dmitry Fazunenko wrote:
>> Hello,
>>
>> May I have to get a couple of reviews for a trivial fix:
>>
>> https://bugs.openjdk.java.net/browse/JDK-8164133
>> http://cr.openjdk.java.net/~dfazunen/8164133/webrev.01/
>>
>> Two tests set very small maximum heap size, which may cause:
>> starts VM with too small heap size, which might cause
>> Error occurred during initialization of VM
>> None of those tests does really require such a small heap, so just
>> increasing should help.
>>
>> Thanks,
>> Dima
>>
>>
>>
>
-------------- next part --------------
[0.009s][trace][gc,heap] Initial heap size 3145728
[0.009s][trace][gc,heap] Minimum heap size 3145728
[0.009s][trace][gc,heap] CMS ergo set MaxNewSize: 700416
[0.009s][trace][gc,heap] CMS set min_heap_size: 3145728 initial_heap_size: 3145728 max_heap: 2097152
[0.009s][trace][gc,heap] CMS ergo set NewSize: 700416
[0.010s][trace][gc,heap] CMS ergo set OldSize: 1396736
[0.010s][trace][gc ] MarkStackSize: 4096k MarkStackSizeMax: 524288k
[0.056s][debug][gc,heap] Minimum heap 4194304 Initial heap 4194304 Maximum heap 4194304
[0.056s][trace][gc,heap] 1: Minimum young 655360 Initial young 655360 Maximum young 655360
[0.056s][trace][gc,heap] Minimum old 65536 Initial old 3538944 Maximum old 3538944
[0.057s][trace][gc,task] WorkerManager::add_workers() : created_workers: 4
[0.057s][trace][gc,task] Adding initial GC Thread(s) previously created workers 0 active workers 4 total created workers 4
[0.057s][trace][gc,heap,coops] Trying to allocate at address 0x00000000ffc00000 heap of size 0x400000
[0.057s][trace][gc,barrier ] CardTableModRefBS::CardTableModRefBS:
[0.057s][trace][gc,barrier ] &_byte_map[0]: 0xffff80ffbe850000 &_byte_map[_last_valid_index]: 0xffff80ffbe851fff
[0.057s][trace][gc,barrier ] byte_map_base: 0xffff80ffbe052000
[0.057s][trace][gc,barrier ] CardTableModRefBS::resize_covered_region:
[0.057s][trace][gc,barrier ] _covered[0].start(): 0x00000000ffc00000 _covered[0].last(): 0x00000000ffc9fff8
[0.057s][trace][gc,barrier ] _committed[0].start(): 0xffff80ffbe850000 _committed[0].last(): 0xffff80ffbe850ff8
[0.057s][trace][gc,barrier ] byte_for(start): 0xffff80ffbe850000 byte_for(last): 0xffff80ffbe8504ff
[0.057s][trace][gc,barrier ] addr_for(start): 0x00000000ffc00000 addr_for(last): 0x00000000ffdff000
[0.057s][trace][gc,bot ] BlockOffsetSharedArray::BlockOffsetSharedArray:
[0.057s][trace][gc,bot ] rs.base(): 0xffff80ffbecb0000 rs.size(): 0x0000000000002000 rs end(): 0xffff80ffbecb2000
[0.057s][trace][gc,bot ] _vs.low_boundary(): 0xffff80ffbecb0000 _vs.high_boundary(): 0xffff80ffbecb2000
[0.057s][trace][gc,barrier ] CardTableModRefBS::resize_covered_region:
[0.057s][trace][gc,barrier ] _covered[1].start(): 0x00000000ffca0000 _covered[1].last(): 0x00000000fffffff8
[0.057s][trace][gc,barrier ] _committed[1].start(): 0xffff80ffbe850000 _committed[1].last(): 0xffff80ffbe851ff8
[0.057s][trace][gc,barrier ] byte_for(start): 0xffff80ffbe850500 byte_for(last): 0xffff80ffbe851fff
[0.057s][trace][gc,barrier ] addr_for(start): 0x00000000ffc00000 addr_for(last): 0x00000000fffff000
[0.058s][debug][gc ] ConcGCThreads: 0
[0.058s][debug][gc ] ParallelGCThreads: 4
[0.059s][info ][gc ] Using Concurrent Mark Sweep
[0.059s][info ][gc,heap,coops] Heap address: 0x00000000ffc00000, size: 4 MB, Compressed Oops mode: 32-bit
[0.059s][trace][gc,metaspace ] space @ 0x000000000048d5a0 0K, 0% used [0x0000000100000000, 0x0000000100000000, 0x0000000100000000, 0x0000000140000000)
[0.059s][trace][gc,metaspace ] Narrow klass base: 0x0000000000000000, Narrow klass shift: 3
[0.059s][trace][gc,metaspace ] Compressed class space size: 1073741824 Address: 0x0000000100000000 Req Addr: 0x0000000100000000
[0.059s][trace][gc,metaspace ] space @ 0x000000000048d710 0K, 0% used [0xffff80ffbd600000, 0xffff80ffbd600000, 0xffff80ffbd600000, 0xffff80ffbde00000)
[0.062s][trace][gc,metaspace,freelist] SpaceManager(): 0x0000000000587070
[0.062s][trace][gc,metaspace,freelist] SpaceManager(): 0x00000000005870e0
[0.062s][debug][gc,metaspace,freelist] VirtualSpaceNode::take_from_committed() not available 524288 words
[0.062s][debug][gc,metaspace,freelist] space @ 0x000000000048d710 0K, 0% used [0xffff80ffbd600000, 0xffff80ffbd600000, 0xffff80ffbd600000, 0xffff80ffbde00000)
[0.062s][trace][gc,metaspace,freelist] SpaceManager::add_chunk: 1)
[0.062s][trace][gc,metaspace,freelist] Metachunk: bottom 0xffff80ffbd600000 top 0xffff80ffbd600028 end 0xffff80ffbda00000 size 524288
[0.062s][trace][gc,metaspace,freelist] Free chunk total 0 count 0
[0.062s][debug][gc,metaspace,freelist] VirtualSpaceNode::take_from_committed() not available 49152 words
[0.062s][debug][gc,metaspace,freelist] space @ 0x000000000048d5a0 0K, 0% used [0x0000000100000000, 0x0000000100000000, 0x0000000100000000, 0x0000000140000000)
[0.062s][trace][gc,metaspace,freelist] SpaceManager::add_chunk: 1)
[0.062s][trace][gc,metaspace,freelist] Metachunk: bottom 0x0000000100000000 top 0x0000000100000028 end 0x0000000100060000 size 49152
[0.062s][trace][gc,metaspace,freelist] Free chunk total 0 count 0
[0.063s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(2) returns 1312
[0.063s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 10KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.069s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(14) returns 1324
[0.069s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 21KB refills: 2 waste 3.2% gc: 0B slow: 664B fast: 0B
[0.075s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(5) returns 1315
[0.075s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 31KB refills: 3 waste 4.0% gc: 0B slow: 1264B fast: 0B
[0.081s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(14) returns 1324
[0.081s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 41KB refills: 4 waste 4.6% gc: 0B slow: 1912B fast: 0B
[0.087s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(14) returns 1324
[0.087s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 52KB refills: 5 waste 4.9% gc: 0B slow: 2576B fast: 0B
[0.089s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(9) returns 1319
[0.089s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 62KB refills: 6 waste 5.1% gc: 0B slow: 3192B fast: 0B
[0.090s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(23) returns 1333
[0.090s][trace][gc,tlab ] TLAB: fill thread: 0x00000000005ea000 [id: 10] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 72KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.090s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(34) returns 1344
[0.090s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 83KB refills: 7 waste 5.2% gc: 0B slow: 3832B fast: 0B
[0.092s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.092s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 0 refill waste: 160B alloc: 0.99945 96KB refills: 8 waste 5.3% gc: 0B slow: 4408B fast: 0B
[0.096s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(130) returns 1440
[0.096s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 224B alloc: 0.99945 108KB refills: 9 waste 5.4% gc: 0B slow: 5096B fast: 0B
[0.098s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.098s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 119KB refills: 10 waste 5.4% gc: 0B slow: 5672B fast: 0B
[0.100s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(4) returns 1314
[0.100s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 129KB refills: 11 waste 5.4% gc: 0B slow: 6272B fast: 0B
[0.102s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(4) returns 1314
[0.102s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 139KB refills: 12 waste 5.5% gc: 0B slow: 6872B fast: 0B
[0.103s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(14) returns 1324
[0.103s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 149KB refills: 13 waste 5.5% gc: 0B slow: 7552B fast: 0B
[0.103s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.103s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 160KB refills: 14 waste 5.5% gc: 0B slow: 8136B fast: 0B
[0.103s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.103s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 170KB refills: 15 waste 5.5% gc: 0B slow: 8712B fast: 0B
[0.104s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.104s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 180KB refills: 16 waste 5.5% gc: 0B slow: 9288B fast: 0B
[0.104s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.104s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 190KB refills: 17 waste 5.5% gc: 0B slow: 9880B fast: 0B
[0.104s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(4) returns 1314
[0.104s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 2 refill waste: 160B alloc: 0.99945 201KB refills: 18 waste 5.5% gc: 0B slow: 10464B fast: 0B
[0.108s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(3) returns 1313
[0.108s][trace][gc,tlab ] TLAB: fill thread: 0x0000000000432800 [id: 2] desired_size: 10KB slow allocs: 6 refill waste: 288B alloc: 0.99945 259KB refills: 19 waste 5.6% gc: 0B slow: 11056B fast: 0B
[0.130s][trace][gc,tlab ] ThreadLocalAllocBuffer::compute_size(2) returns failure
[0.130s][trace][gc,alloc ] GenCollectorPolicy::mem_allocate_work: attempting locked slow path allocation
[0.130s][trace][gc,alloc ] DefNewGeneration::allocate_from_space(2): will_fail: false heap_lock: locked free: 65536 should_allocate_from_space: NOT returns NULL
Error occurred during initialization of VM
GC triggered before VM initialization completed. Try increasing NewSize, current value 640K.
More information about the hotspot-gc-dev
mailing list