Strange behaviour on half-occupied heap

[Simon Ogorodnik]

> On 29 Aug 2018, at 12:08, Aleksey Shipilev <shade at redhat.com> wrote:
> 
> 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

I think that homogenous fragmentation is not an origin of the problem, as it was only triggering to fall into Full GC

Here other similar situation, but with a whole heap full of ’Shared allocs’

According to HPROF heap dump before Full GC, there are 1.3 GB of 'Objects unreachable from GC roots, but not yet collected, Retained 1378197088’
But GC didn’t bother to clear it before Full GC

After Full GC house objects actually got cleaned up

GCLogs & HPROF’s
https://drive.google.com/file/d/1oNdTsRMcb_DBoBnTbkZgoxSqkaGkz6Oi/view?usp=sharing <https://drive.google.com/file/d/1oNdTsRMcb_DBoBnTbkZgoxSqkaGkz6Oi/view?usp=sharing>


Trigger: Free (42M) is below minimum threshold (204M)
Free set: Used: 0M of 42M, Regions: 214 mutator, 0 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 2048K, External frag: 96%, Internal frag: 80%
Free set: Collector view: Max regular: 0K
2018-08-29T16:27:30.867-0300: 2217.450: [Pause Init MarkUsing 8 of 8 workers for init marking
Pacer for Mark. Expected Live: 1625M, Free: 41M, Non-Taxable: 4M, Alloc Tax Rate: 144.2x
, 14.115 ms]
2018-08-29T16:27:30.881-0300: 2217.464: Total time for which application threads were stopped: 0.0184063 seconds, Stopping threads took: 0.0010524 seconds
2018-08-29T16:27:30.881-0300: 2217.464: [Concurrent markingUsing 8 of 8 workers for concurrent marking
 2002M->2014M(2048M), 163.084 ms]
2018-08-29T16:27:31.044-0300: 2217.627: Application time: 0.1632269 seconds
2018-08-29T16:27:31.045-0300: 2217.627: [Pause Final MarkUsing 8 of 8 workers for final marking
Adaptive CSet Selection. Target Free: 204M, Actual Free: 0M, Max CSet: 0M, Min Garbage: 204M

Looks like it size of collectable garbage is wrong, because of according to heap dump there are actually 1.3G of not yet collected garbage 

Collectable Garbage: 0M (0% of total), 0M CSet, 0 CSet regions 
Immediate Garbage: 0M (0% of total), 0 regions
Free: 29M, Regions: 207 mutator, 0 collector
Pacer for Evacuation. Used CSet: 0M, Avail: 29M, Non-Taxable: 2M, Alloc Tax Rate: 1.1x
, 1.067 ms]
2018-08-29T16:27:31.046-0300: 2217.629: Total time for which application threads were stopped: 0.0015229 seconds, Stopping threads took: 0.0000455 seconds
2018-08-29T16:27:31.046-0300: 2217.629: [Concurrent cleanupUsing 8 of 8 workers for concurrent cleanup
 2014M->2015M(2048M), 5.132 ms]
Free set: Used: 1M of 29M, Regions: 180 mutator, 0 collector
Free set: Mutator view: Max regular: 255K, Max humongous: 0K, External frag: 100%, Internal frag: 84%
Free set: Collector view: Max regular: 0K
Pacer for Idle. Initial: 40M, Alloc Tax Rate: 1.0x
Trigger: Free (27M) is below minimum threshold (204M)
Free set: Used: 2M of 29M, Regions: 171 mutator, 0 collector
Free set: Mutator view: Max regular: 255K, Max humongous: 0K, External frag: 100%, Internal frag: 83%
Free set: Collector view: Max regular: 0K
2018-08-29T16:27:31.053-0300: 2217.635: Application time: 0.0067195 seconds
2018-08-29T16:27:31.053-0300: 2217.636: [Pause Init MarkUsing 8 of 8 workers for init marking
Pacer for Mark. Expected Live: 1626M, Free: 27M, Non-Taxable: 2M, Alloc Tax Rate: 217.3x
, 18.124 ms]
2018-08-29T16:27:31.071-0300: 2217.654: Total time for which application threads were stopped: 0.0186765 seconds, Stopping threads took: 0.0001512 seconds
2018-08-29T16:27:31.071-0300: 2217.654: [Concurrent markingUsing 8 of 8 workers for concurrent marking
Failed to allocate 288K
Cancelling GC: Allocation Failure
 2016M->2021M(2048M), 136.924 ms]
Free set: Used: 29M of 29M, Regions: 0 mutator, 0 collector
Free set: Mutator view: Max regular: 0K, Max humongous: 0K, External frag: 0%, Internal frag: 0%
Free set: Collector view: Max regular: 0K
Pacer for Idle. Initial: 40M, Alloc Tax Rate: 1.0x
Trigger: Handle Allocation Failure
Free set: Used: 29M of 29M, Regions: 0 mutator, 0 collector
Free set: Mutator view: Max regular: 0K, Max humongous: 0K, External frag: 0%, Internal frag: 0%
Free set: Collector view: Max regular: 0K
2018-08-29T16:27:31.209-0300: 2217.792: Application time: 0.1382200 seconds
2018-08-29T16:27:31.210-0300: 2217.793: [Pause Degenerated GC (Mark)Using 8 of 8 workers for stw degenerated gc
Adaptive CSet Selection. Target Free: 204M, Actual Free: 0M, Max CSet: 0M, Min Garbage: 204M
Collectable Garbage: 0M (0% of total), 0M CSet, 0 CSet regions
Immediate Garbage: 0M (0% of total), 0 regions
Free: 22M, Regions: 176 mutator, 0 collector
Pacer for Evacuation. Used CSet: 0M, Avail: 22M, Non-Taxable: 2M, Alloc Tax Rate: 1.1x
Used: before: 2021M, after: 2021M
Internal frag: before: 0.9%, after: 0.9%
External frag: before: 100.0%, after: 100.0%
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: 1778M, Regions: 2005 mutator, 0 collector
Used: before: 2021M, after: 265M
Internal frag: before: 0.9%, after: 1.0%
External frag: before: 100.0%, after: 41.7%
 2021M->265M(2048M), 2450.265 ms]