Strange behaviour on half-occupied heap

[Aleksey Shipilev]

Hi,

On 08/28/2018 09:19 PM, Simon Ogorodnik wrote:
> I faced some problems building JDK 8 for Win64 with latest changes
> Problems: 
> ...\hotspot\src\share\vm\gc_implementation\shenandoah\shenandoahHeapRegion.cpp(566) : error C2220:
> warning treated as error - no 'object' file generated
> ...\hotspot\src\share\vm\gc_implementation\shenandoah\shenandoahHeapRegion.cpp(566) : warning C4334:
> '<<' : result of 32-bit shift implicitly converted to 64 bits (was 64-bit shift intended?)
> ...\hotspot\src\share\vm\gc_implementation\shenandoah\shenandoahPhaseTimings.cpp(34) : error C2220:
> warning treated as error - no 'object' file generated
> ...\hotspot\src\share\vm\gc_implementation\shenandoah\shenandoahPhaseTimings.cpp(34) : warning
> C4267: 'initializing' : conversion from 'size_t' to 'uint', possible loss of data
> Here is my patch: https://drive.google.com/file/d/1zZ_w_KqdAtZf8TP0nCZ2f-2FC4jrVvV2/view?usp=sharing

Thanks, we shall push the variant of that fix to our dev repo, and then it shall propagate to sh/jdk8.


> Looks like the original problem fixed, but new very possible related problem opens up with a fix.
> 
> After a bit of time heap fills with fragmented data. 
> Which results in the increasing rate of collections, pacing delays and finally full GC, 
> while actually there are 350 MB of live data it fills whole 2G heap

This problem is unrelated: it is humongous fragmentation, see the log comments below. This can be
mitigated by giving Shenandoah larger heap (so that fragmentation goes down, and some humongous
objects stop being humongous too). Let's see if there are Shenandoah fixes that can help mitigate
this too.

I think Full GC reclaims much more memory because it also processes references unconditionally, and
unloads the classes. I believe this is why "Expected Live" is larger than the used space after Full
GC. Degenerated GC should clean up references like that too, so we can avoid diving into Full GC:
  http://hg.openjdk.java.net/shenandoah/jdk/rev/7b1902800e63

What had happened in the log:

; trying to allocate 25M object, and failing
Failed to allocate 25M
Cancelling GC: Allocation Failure
Trigger: Handle Allocation Failure

; because max humongous is only 14M (heap is too fragmented)
Free set: Used: 55M of 313M, Regions: 386 mutator, 0 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 14336K, External frag: 95%, Internal
frag: 33%
Free set: Collector view: Max regular: 0K

; Degenerated GC proceeds to clean up some space
Pacer for Mark. Expected Live: 1161M, Free: 257M, Non-Taxable: 25M, Alloc Tax Rate: 16.5x
Adaptive CSet Selection. Target Free: 204M, Actual Free: 201M, Max CSet: 50M, Min Garbage: 3M
Collectable Garbage: 139M (23% of total), 7M CSet, 147 CSet regions
Immediate Garbage: 4M (0% of total), 4 regions
Free: 261M, Regions: 396 mutator, 0 collector
Pacer for Evacuation. Used CSet: 146M, Avail: 253M, Non-Taxable: 25M, Alloc Tax Rate: 1.4x
Pacer for Update Refs. Used: 1756M, Free: 253M, Non-Taxable: 25M, Alloc Tax Rate: 8.5x
Free: 400M, Regions: 536 mutator, 0 collector
Used: before: 1752M, after: 1610M
Internal frag: before: 2.2%, after: 2.3%
External frag: before: 94.9%, after: 96.6%
 1752M->1610M(2048M), 265.637 ms]
Free set: Used: 0M of 400M, Regions: 536 mutator, 0 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 14336K, External frag: 97%, Internal
frag: 25%
Free set: Collector view: Max regular: 0K

; and allocation retries, but still not enough space to fit 25M object:
Failed to allocate 25M
Cancelling GC: Allocation Failure
Pacer for Idle. Initial: 40M, Alloc Tax Rate: 1.0x
Trigger: Handle Allocation Failure
Free set: Used: 0M of 400M, Regions: 536 mutator, 0 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 14336K, External frag: 97%, Internal
frag: 25%
Free set: Collector view: Max regular: 0K

; ...so Degenerated GC tries again:
2018-08-28T20:54:40.090-0300: 1520.821: [Pause Degenerated GC (Outside of Cycle)Using 8 of 8 workers
for stw degenerated gc
Pacer for Mark. Expected Live: 1161M, Free: 400M, Non-Taxable: 40M, Alloc Tax Rate: 10.6x
Adaptive CSet Selection. Target Free: 204M, Actual Free: 339M, Max CSet: 84M, Min Garbage: 0M
Collectable Garbage: 0M (0% of total), 0M CSet, 0 CSet regions
Immediate Garbage: 0M (0% of total), 0 regions
Free: 400M, Regions: 536 mutator, 0 collector
Pacer for Evacuation. Used CSet: 0M, Avail: 400M, Non-Taxable: 40M, Alloc Tax Rate: 1.1x
Used: before: 1610M, after: 1610M
Internal frag: before: 2.3%, after: 2.3%
External frag: before: 96.6%, after: 96.6%

; ...but everything proper was collected during previous degen,
; so there is no other way than to force Full GC
Not enough progress (0M, need 1M) after Degenerated GC
Not enough internal fragmentation improvement (0.0%, need 1.0%) after Degenerated GC
Not enough external fragmentation improvement (0.0%, need 1.0%) after Degenerated GC
Cancelling GC: Shenandoah Upgrade To Full GC
Free: 1550M, Regions: 1939 mutator, 0 collector
Used: before: 1610M, after: 493M
Internal frag: before: 2.3%, after: 0.8%
External frag: before: 96.6%, after: 55.4%
 1610M->493M(2048M), 763.914 ms]
2018-08-28T20:54:40.854-0300: 1521.585: Total time for which application threads were stopped:
0.7643449 seconds, Stopping threads took: 0.0000241 seconds

; ...which compacts the heap, so that we get the 710M piece where we can fit the allocation:
Free set: Used: 0M of 1550M, Regions: 1938 mutator, 0 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 710656K, External frag: 56%, Internal
frag: 19%
Free set: Collector view: Max regular: 0K
Pacer for Idle. Initial: 40M, Alloc Tax Rate: 1.0x


Thanks,
-Aleksey