Strange behaviour on half-occupied heap

Fri Aug 10 15:22:45 UTC 2018

Sometime after long run (8-9 hours with almost half-occupied heap) of application with Shenandoah GC, I observe strange behaviour
I can describe it as continuous evacuation of whole GCLAB. 

If allocation pressure lowers it stops to reproduce continuously, but begins again after next GC

View in Shenandoah Visualiser: 
https://drive.google.com/file/d/1U_TXAEMqKoQNcMMmt3pcCcCKsUVtK1Sm/view?usp=sharing <https://drive.google.com/file/d/1U_TXAEMqKoQNcMMmt3pcCcCKsUVtK1Sm/view?usp=sharing>
Recorded on:
https://github.com/JetBrains/jdk8u_hotspot/commit/65c26b4995d46dc0136a57a3d964fe9557049894 <https://github.com/JetBrains/jdk8u_hotspot/commit/65c26b4995d46dc0136a57a3d964fe9557049894>
Which is correspond to http://hg.openjdk.java.net/shenandoah/jdk8u/hotspot/rev/3454fc2dcb16 <http://hg.openjdk.java.net/shenandoah/jdk8u/hotspot/rev/3454fc2dcb16>

Sometime later I captured GC logs during that process
Full logs:
1: https://drive.google.com/file/d/1j8r8eh64v12TcxREZNOL-temrV88IGk6/view?usp=sharing <https://drive.google.com/file/d/1j8r8eh64v12TcxREZNOL-temrV88IGk6/view?usp=sharing>
2: https://drive.google.com/file/d/1udYKZlNCzwOiS7NRLCpxUvgE7JKHz6xS/view?usp=sharing <https://drive.google.com/file/d/1udYKZlNCzwOiS7NRLCpxUvgE7JKHz6xS/view?usp=sharing>
Recorded on:
https://github.com/JetBrains/jdk8u_hotspot/commit/20e1fb074d604d621f45bb8b1365ac3ccbd3820c <https://github.com/JetBrains/jdk8u_hotspot/commit/20e1fb074d604d621f45bb8b1365ac3ccbd3820c>
Which is correspond to http://hg.openjdk.java.net/shenandoah/jdk8u/hotspot/rev/3a26162cc4c6 <http://hg.openjdk.java.net/shenandoah/jdk8u/hotspot/rev/3a26162cc4c6>

….
2018-08-08T19:19:11.528-0300: 34458.816: [Concurrent cleanupUsing 8 of 8 workers for concurrent cleanup
 1870M->1872M(2048M), 13.076 ms]
Capacity: 2048M, Peak Occupancy: 1872M, Lowest Free: 175M, Free Threshold: 204M
Adjusting free threshold to: 69% (1413M)
Free set: Used: 793M of 959M, Regions: 173 mutator, 1 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 74752K, External frag: 57%, Internal frag: 4%
Free set: Collector view: Max regular: 499K
Pacer for Idle. Initial: 40M, Alloc Tax Rate: 1.0x
Concurrent marking triggered. Free: 166M, Free Threshold: 1413M; Allocated: 861M, Alloc Threshold: 0M
Free set: Used: 793M of 959M, Regions: 173 mutator, 1 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 74752K, External frag: 57%, Internal frag: 4%
Free set: Collector view: Max regular: 499K
2018-08-08T19:19:11.542-0300: 34458.831: Application time: 0.0144885 seconds
2018-08-08T19:19:11.543-0300: 34458.832: [Pause Init Mark (update refs)Using 8 of 8 workers for init marking
Pacer for Mark. Expected Live: 892M, Free: 166M, Non-Taxable: 16M, Alloc Tax Rate: 19.7x
, 16.607 ms]
2018-08-08T19:19:11.559-0300: 34458.848: Total time for which application threads were stopped: 0.0173111 seconds, Stopping threads took: 0.0000844 seconds
2018-08-08T19:19:11.559-0300: 34458.848: [Concurrent marking (update refs)Using 8 of 8 workers for concurrent marking
 1872M->1909M(2048M), 817.864 ms]
2018-08-08T19:19:12.377-0300: 34459.666: Application time: 0.8180063 seconds
2018-08-08T19:19:12.379-0300: 34459.668: [Pause Final Mark (update refs)Using 8 of 8 workers for final marking
Adaptive CSet Selection. Target Free: 1515M, Actual Free: 969M, Max CSet: 727M, Min Garbage: 546M
Collectable Garbage: 104M (10% of total), 726M CSet, 834 CSet regions
Immediate Garbage: 844M (88% of total), 847 regions
Free: 975M, Regions: 998 mutator, 0 collector
Pacer for Evacuation. Used CSet: 831M, Avail: 245M, Non-Taxable: 24M, Alloc Tax Rate: 8.3x
, 41.287 ms]
2018-08-08T19:19:12.421-0300: 34459.710: Total time for which application threads were stopped: 0.0432889 seconds, Stopping threads took: 0.0001214 seconds
2018-08-08T19:19:12.421-0300: 34459.710: [Concurrent cleanup 1909M->1070M(2048M), 0.239 ms]
2018-08-08T19:19:12.421-0300: 34459.710: [Concurrent evacuationUsing 8 of 8 workers for concurrent evacuation
 1070M->1902M(2048M), 413.805 ms]
2018-08-08T19:19:12.835-0300: 34460.124: Application time: 0.4142264 seconds
2018-08-08T19:19:12.837-0300: 34460.126: [Pause Final Evac, 0.067 ms]
2018-08-08T19:19:12.837-0300: 34460.126: Total time for which application threads were stopped: 0.0020021 seconds, Stopping threads took: 0.0011507 seconds
2018-08-08T19:19:12.837-0300: 34460.126: [Concurrent cleanupUsing 8 of 8 workers for concurrent cleanup
 1902M->1903M(2048M), 2.577 ms]
Capacity: 2048M, Peak Occupancy: 1910M, Lowest Free: 137M, Free Threshold: 204M
Adjusting free threshold to: 70% (1433M)
Free set: Used: 842M of 975M, Regions: 155 mutator, 1 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 68608K, External frag: 50%, Internal frag: 14%
Free set: Collector view: Max regular: 384K
Pacer for Idle. Initial: 40M, Alloc Tax Rate: 1.0x
Concurrent marking triggered. Free: 132M, Free Threshold: 1433M; Allocated: 920M, Alloc Threshold: 0M
Free set: Used: 843M of 975M, Regions: 155 mutator, 1 collector
Free set: Mutator view: Max regular: 1024K, Max humongous: 68608K, External frag: 50%, Internal frag: 14%
Free set: Collector view: Max regular: 384K
2018-08-08T19:19:12.841-0300: 34460.130: Application time: 0.0040286 seconds
2018-08-08T19:19:12.842-0300: 34460.130: [Pause Init Mark (update refs)Using 8 of 8 workers for init marking
Pacer for Mark. Expected Live: 901M, Free: 132M, Non-Taxable: 13M, Alloc Tax Rate: 24.9x
, 16.006 ms]
2018-08-08T19:19:12.858-0300: 34460.147: Total time for which application threads were stopped: 0.0167590 seconds, Stopping threads took: 0.0001621 seconds
2018-08-08T19:19:12.858-0300: 34460.147: [Concurrent marking (update refs)Using 8 of 8 workers for concurrent marking
 1903M->1943M(2048M), 992.342 ms]
2018-08-08T19:19:13.850-0300: 34461.139: Application time: 0.9925162 seconds
2018-08-08T19:19:13.851-0300: 34461.140: [Pause Final Mark (update refs)Using 8 of 8 workers for final marking
Adaptive CSet Selection. Target Free: 1536M, Actual Free: 919M, Max CSet: 689M, Min Garbage: 616M
Collectable Garbage: 128M (13% of total), 688M CSet, 822 CSet regions
Immediate Garbage: 832M (86% of total), 836 regions
Free: 927M, Regions: 958 mutator, 0 collector
Pacer for Evacuation. Used CSet: 817M, Avail: 235M, Non-Taxable: 23M, Alloc Tax Rate: 8.5x
, 39.205 ms]
2018-08-08T19:19:13.890-0300: 34461.179: Total time for which application threads were stopped: 0.0401316 seconds, Stopping threads took: 0.0001217 seconds
2018-08-08T19:19:13.890-0300: 34461.179: [Concurrent cleanup 1942M->1116M(2048M), 0.255 ms]
2018-08-08T19:19:13.891-0300: 34461.180: [Concurrent evacuationUsing 8 of 8 workers for concurrent evacuation
2018-08-08T19:19:14.058-0300: 34461.347: Application time: 0.1673611 seconds
2018-08-08T19:19:14.066-0300: 34461.355: Total time for which application threads were stopped: 0.0088015 seconds, Stopping threads took: 0.0001226 seconds
 1116M->1920M(2048M), 312.858 ms]
2018-08-08T19:19:14.203-0300: 34461.492: Application time: 0.1371588 seconds
2018-08-08T19:19:14.205-0300: 34461.494: [Pause Final Evac, 0.071 ms]
2018-08-08T19:19:14.205-0300: 34461.494: Total time for which application threads were stopped: 0.0018166 seconds, Stopping threads took: 0.0006766 seconds
…. Similar repeats

Thanks, 
- Simon Ogorodnik 