JVM not using all available heap space

Question

I'm trying to understand G1 garbage collection logs. Most important details you may find in the top of the log file. Heap max capacity is 594M, but the latest garbage collection cycle had used only 351M, before the jvm exit. Jvm crashed with java.lang.OutOfMemoryError: Java heap space

[05:58:15.812][info][gc] Using G1
[05:58:15.831][info][gc,init] Version: 17.0.4.1+9-LTS (release)
[05:58:15.843][info][gc,init] CPUs: 6 total, 6 available
[05:58:15.844][info][gc,init] Memory: 1536M
[05:58:15.845][info][gc,init] Large Page Support: Disabled
[05:58:15.846][info][gc,init] NUMA Support: Disabled
[05:58:15.846][info][gc,init] Compressed Oops: Enabled (32-bit)
[05:58:15.846][info][gc,init] Heap Region Size: 1M
[05:58:15.847][info][gc,init] Heap Min Capacity: 594M
[05:58:15.847][info][gc,init] Heap Initial Capacity: 594M
[05:58:15.847][info][gc,init] Heap Max Capacity: 594M
[05:58:15.847][info][gc,init] Pre-touch: Disabled
[05:58:15.847][info][gc,init] Parallel Workers: 6
[05:58:15.847][info][gc,init] Concurrent Workers: 2
[05:58:15.849][info][gc,init] Concurrent Refinement Workers: 6
[05:58:15.849][info][gc,init] Periodic GC: Disabled
...
[06:01:10.226][info][gc          ] GC(15) Pause Young (Normal) (G1 Evacuation Pause) 231M->69M(594M) 152.677ms
[06:01:10.228][info][gc,cpu      ] GC(15) User=0.08s Sys=0.08s Real=0.16s
[06:01:13.502][info][gc,start    ] GC(16) Pause Young (Normal) (G1 Evacuation Pause)
[06:01:13.504][info][gc,task     ] GC(16) Using 6 workers of 6 for evacuation
[06:01:13.661][info][gc,phases   ] GC(16)   Pre Evacuate Collection Set: 2.0ms
[06:01:13.663][info][gc,phases   ] GC(16)   Merge Heap Roots: 1.4ms
[06:01:13.664][info][gc,phases   ] GC(16)   Evacuate Collection Set: 125.0ms
[06:01:13.669][info][gc,phases   ] GC(16)   Post Evacuate Collection Set: 25.1ms
[06:01:13.670][info][gc,phases   ] GC(16)   Other: 6.0ms
[06:01:13.671][info][gc,heap     ] GC(16) Eden regions: 46->0(330)
[06:01:13.673][info][gc,heap     ] GC(16) Survivor regions: 20->3(9)
[06:01:13.675][info][gc,heap     ] GC(16) Old regions: 42->61
[06:01:13.678][info][gc,heap     ] GC(16) Archive regions: 2->2
[06:01:13.681][info][gc,heap     ] GC(16) Humongous regions: 7->7
[06:01:13.685][info][gc,metaspace] GC(16) Metaspace: 80929K(81856K)->80929K(81856K) NonClass: 70613K(71040K)->70613K(71040K) Class: 10316K(10816K)->10316K(10816K)
[06:01:13.689][info][gc          ] GC(16) Pause Young (Normal) (G1 Evacuation Pause) 115M->71M(594M) 186.642ms
[06:01:13.691][info][gc,cpu      ] GC(16) User=0.14s Sys=0.10s Real=0.19s
[06:01:20.646][info][gc,start    ] GC(17) Pause Young (Normal) (G1 Evacuation Pause)
[06:01:20.648][info][gc,task     ] GC(17) Using 6 workers of 6 for evacuation
[06:01:20.697][info][gc,phases   ] GC(17)   Pre Evacuate Collection Set: 0.2ms
[06:01:20.698][info][gc,phases   ] GC(17)   Merge Heap Roots: 3.4ms
[06:01:20.699][info][gc,phases   ] GC(17)   Evacuate Collection Set: 25.8ms
[06:01:20.700][info][gc,phases   ] GC(17)   Post Evacuate Collection Set: 17.2ms
[06:01:20.701][info][gc,phases   ] GC(17)   Other: 3.7ms
[06:01:20.701][info][gc,heap     ] GC(17) Eden regions: 330->0(349)
[06:01:20.703][info][gc,heap     ] GC(17) Survivor regions: 3->7(42)
[06:01:20.703][info][gc,heap     ] GC(17) Old regions: 61->61
[06:01:20.704][info][gc,heap     ] GC(17) Archive regions: 2->2
[06:01:20.704][info][gc,heap     ] GC(17) Humongous regions: 7->7
[06:01:20.705][info][gc,metaspace] GC(17) Metaspace: 86881K(87808K)->86881K(87808K) NonClass: 75830K(76288K)->75830K(76288K) Class: 11050K(11520K)->11050K(11520K)
[06:01:20.707][info][gc          ] GC(17) Pause Young (Normal) (G1 Evacuation Pause) 401M->74M(594M) 60.350ms
[06:01:20.708][info][gc,cpu      ] GC(17) User=0.07s Sys=0.09s Real=0.07s
[06:01:28.403][info][gc,start    ] GC(18) Pause Young (Normal) (G1 Evacuation Pause)
[06:01:28.404][info][gc,task     ] GC(18) Using 6 workers of 6 for evacuation
[06:01:28.458][info][gc,phases   ] GC(18)   Pre Evacuate Collection Set: 1.8ms
[06:01:28.459][info][gc,phases   ] GC(18)   Merge Heap Roots: 1.5ms
[06:01:28.460][info][gc,phases   ] GC(18)   Evacuate Collection Set: 39.3ms
[06:01:28.462][info][gc,phases   ] GC(18)   Post Evacuate Collection Set: 10.1ms
[06:01:28.463][info][gc,phases   ] GC(18)   Other: 2.8ms
[06:01:28.463][info][gc,heap     ] GC(18) Eden regions: 349->0(144)
[06:01:28.466][info][gc,heap     ] GC(18) Survivor regions: 7->39(45)
[06:01:28.466][info][gc,heap     ] GC(18) Old regions: 61->61
[06:01:28.468][info][gc,heap     ] GC(18) Archive regions: 2->2
[06:01:28.468][info][gc,heap     ] GC(18) Humongous regions: 11->11
[06:01:28.468][info][gc,metaspace] GC(18) Metaspace: 97955K(98944K)->97955K(98944K) NonClass: 85583K(86016K)->85583K(86016K) Class: 12371K(12928K)->12371K(12928K)
[06:01:28.468][info][gc          ] GC(18) Pause Young (Normal) (G1 Evacuation Pause) 427M->110M(594M) 65.566ms
[06:01:28.469][info][gc,cpu      ] GC(18) User=0.18s Sys=0.08s Real=0.07s
[06:01:30.412][info][gc,start    ] GC(19) Pause Young (Normal) (G1 Evacuation Pause)
[06:01:30.412][info][gc,task     ] GC(19) Using 6 workers of 6 for evacuation
[06:01:30.478][info][gc,phases   ] GC(19)   Pre Evacuate Collection Set: 1.0ms
[06:01:30.479][info][gc,phases   ] GC(19)   Merge Heap Roots: 1.4ms
[06:01:30.480][info][gc,phases   ] GC(19)   Evacuate Collection Set: 54.0ms
[06:01:30.480][info][gc,phases   ] GC(19)   Post Evacuate Collection Set: 8.6ms
[06:01:30.481][info][gc,phases   ] GC(19)   Other: 1.8ms
[06:01:30.481][info][gc,heap     ] GC(19) Eden regions: 144->0(348)
[06:01:30.481][info][gc,heap     ] GC(19) Survivor regions: 39->8(23)
[06:01:30.481][info][gc,heap     ] GC(19) Old regions: 61->99
[06:01:30.481][info][gc,heap     ] GC(19) Archive regions: 2->2
[06:01:30.484][info][gc,heap     ] GC(19) Humongous regions: 13->11
[06:01:30.485][info][gc,metaspace] GC(19) Metaspace: 104263K(105216K)->104263K(105216K) NonClass: 91248K(91712K)->91248K(91712K) Class: 13015K(13504K)->13015K(13504K)
[06:01:30.487][info][gc          ] GC(19) Pause Young (Normal) (G1 Evacuation Pause) 256M->117M(594M) 74.925ms
[06:01:30.487][info][gc,cpu      ] GC(19) User=0.09s Sys=0.10s Real=0.08s
[06:01:35.850][info][gc,start    ] GC(20) Pause Young (Concurrent Start) (Metadata GC Threshold)
[06:01:35.851][info][gc,task     ] GC(20) Using 6 workers of 6 for evacuation
[06:01:35.897][info][gc,phases   ] GC(20)   Pre Evacuate Collection Set: 1.0ms
[06:01:35.898][info][gc,phases   ] GC(20)   Merge Heap Roots: 2.2ms
[06:01:35.898][info][gc,phases   ] GC(20)   Evacuate Collection Set: 31.2ms
[06:01:35.899][info][gc,phases   ] GC(20)   Post Evacuate Collection Set: 9.2ms
[06:01:35.900][info][gc,phases   ] GC(20)   Other: 2.8ms
[06:01:35.902][info][gc,heap     ] GC(20) Eden regions: 335->0(343)
[06:01:35.903][info][gc,heap     ] GC(20) Survivor regions: 8->13(45)
[06:01:35.903][info][gc,heap     ] GC(20) Old regions: 99->99
[06:01:35.905][info][gc,heap     ] GC(20) Archive regions: 2->2
[06:01:35.907][info][gc,heap     ] GC(20) Humongous regions: 11->11
[06:01:35.907][info][gc,metaspace] GC(20) Metaspace: 111583K(112640K)->111583K(112640K) NonClass: 97634K(98176K)->97634K(98176K) Class: 13949K(14464K)->13949K(14464K)
[06:01:35.911][info][gc          ] GC(20) Pause Young (Concurrent Start) (Metadata GC Threshold) 452M->122M(594M) 60.235ms
[06:01:35.912][info][gc,cpu      ] GC(20) User=0.06s Sys=0.13s Real=0.06s
[06:01:35.913][info][gc          ] GC(21) Concurrent Mark Cycle
[06:01:35.913][info][gc,marking  ] GC(21) Concurrent Clear Claimed Marks
[06:01:35.915][info][gc,marking  ] GC(21) Concurrent Clear Claimed Marks 1.447ms
[06:01:35.916][info][gc,marking  ] GC(21) Concurrent Scan Root Regions
[06:01:35.954][info][gc,marking  ] GC(21) Concurrent Scan Root Regions 38.159ms
[06:01:35.959][info][gc,marking  ] GC(21) Concurrent Mark
[06:01:35.961][info][gc,marking  ] GC(21) Concurrent Mark From Roots
[06:01:35.961][info][gc,task     ] GC(21) Using 2 workers of 2 for marking
[06:01:36.052][info][gc,marking  ] GC(21) Concurrent Mark From Roots 91.284ms
[06:01:36.053][info][gc,marking  ] GC(21) Concurrent Preclean
[06:01:36.056][info][gc,marking  ] GC(21) Concurrent Preclean 3.797ms
[06:01:36.060][info][gc,start    ] GC(21) Pause Remark
[06:01:36.101][info][gc          ] GC(21) Pause Remark 127M->126M(594M) 40.502ms
[06:01:36.101][info][gc,cpu      ] GC(21) User=0.09s Sys=0.05s Real=0.04s
[06:01:36.108][info][gc,marking  ] GC(21) Concurrent Mark 148.167ms
[06:01:36.111][info][gc,marking  ] GC(21) Concurrent Rebuild Remembered Sets
[06:01:36.237][info][gc,marking  ] GC(21) Concurrent Rebuild Remembered Sets 126.496ms
[06:01:36.254][info][gc,start    ] GC(21) Pause Cleanup
[06:01:36.256][info][gc          ] GC(21) Pause Cleanup 128M->128M(594M) 2.162ms
[06:01:36.256][info][gc,cpu      ] GC(21) User=0.00s Sys=0.00s Real=0.00s
[06:01:36.259][info][gc,marking  ] GC(21) Concurrent Cleanup for Next Mark
[06:01:36.264][info][gc,marking  ] GC(21) Concurrent Cleanup for Next Mark 5.166ms
[06:01:36.266][info][gc          ] GC(21) Concurrent Mark Cycle 352.545ms
[06:01:43.740][info][gc,start    ] GC(22) Pause Young (Prepare Mixed) (G1 Evacuation Pause)
[06:01:43.741][info][gc,task     ] GC(22) Using 6 workers of 6 for evacuation
[06:01:43.844][info][gc,phases   ] GC(22)   Pre Evacuate Collection Set: 0.5ms
[06:01:43.845][info][gc,phases   ] GC(22)   Merge Heap Roots: 4.1ms
[06:01:43.847][info][gc,phases   ] GC(22)   Evacuate Collection Set: 61.2ms
[06:01:43.849][info][gc,phases   ] GC(22)   Post Evacuate Collection Set: 30.9ms
[06:01:43.850][info][gc,phases   ] GC(22)   Other: 7.4ms
[06:01:43.851][info][gc,heap     ] GC(22) Eden regions: 343->0(8)
[06:01:43.852][info][gc,heap     ] GC(22) Survivor regions: 13->21(45)
[06:01:43.852][info][gc,heap     ] GC(22) Old regions: 99->99
[06:01:43.852][info][gc,heap     ] GC(22) Archive regions: 2->2
[06:01:43.853][info][gc,heap     ] GC(22) Humongous regions: 10->10
[06:01:43.854][info][gc,metaspace] GC(22) Metaspace: 119561K(120704K)->119561K(120704K) NonClass: 104432K(104960K)->104432K(104960K) Class: 15128K(15744K)->15128K(15744K)
[06:01:43.858][info][gc          ] GC(22) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 464M->129M(594M) 118.686ms
[06:01:43.860][info][gc,cpu      ] GC(22) User=0.07s Sys=0.13s Real=0.12s
[06:01:44.034][info][gc,start    ] GC(23) Pause Young (Mixed) (G1 Evacuation Pause)
[06:01:44.037][info][gc,task     ] GC(23) Using 6 workers of 6 for evacuation
[06:01:44.150][info][gc,phases   ] GC(23)   Pre Evacuate Collection Set: 0.5ms
[06:01:44.151][info][gc,phases   ] GC(23)   Merge Heap Roots: 2.5ms
[06:01:44.152][info][gc,phases   ] GC(23)   Evacuate Collection Set: 85.8ms
[06:01:44.153][info][gc,phases   ] GC(23)   Post Evacuate Collection Set: 20.3ms
[06:01:44.155][info][gc,phases   ] GC(23)   Other: 7.5ms
[06:01:44.155][info][gc,heap     ] GC(23) Eden regions: 8->0(354)
[06:01:44.157][info][gc,heap     ] GC(23) Survivor regions: 21->2(4)
[06:01:44.160][info][gc,heap     ] GC(23) Old regions: 99->117
[06:01:44.160][info][gc,heap     ] GC(23) Archive regions: 2->2
[06:01:44.173][info][gc,heap     ] GC(23) Humongous regions: 10->10
[06:01:44.173][info][gc,metaspace] GC(23) Metaspace: 119798K(120896K)->119798K(120896K) NonClass: 104634K(105152K)->104634K(105152K) Class: 15164K(15744K)->15164K(15744K)
[06:01:44.179][info][gc          ] GC(23) Pause Young (Mixed) (G1 Evacuation Pause) 137M->129M(594M) 145.364ms
[06:01:44.184][info][gc,cpu      ] GC(23) User=0.04s Sys=0.08s Real=0.15s
[06:02:06.822][info][gc,start    ] GC(24) Pause Young (Normal) (G1 Evacuation Pause)
[06:02:06.822][info][gc,task     ] GC(24) Using 6 workers of 6 for evacuation
[06:02:06.969][info][gc,phases   ] GC(24)   Pre Evacuate Collection Set: 0.4ms
[06:02:06.970][info][gc,phases   ] GC(24)   Merge Heap Roots: 1.4ms
[06:02:06.970][info][gc,phases   ] GC(24)   Evacuate Collection Set: 124.4ms
[06:02:06.970][info][gc,phases   ] GC(24)   Post Evacuate Collection Set: 18.6ms
[06:02:06.970][info][gc,phases   ] GC(24)   Other: 2.7ms
[06:02:06.971][info][gc,heap     ] GC(24) Eden regions: 354->0(153)
[06:02:06.972][info][gc,heap     ] GC(24) Survivor regions: 2->37(45)
[06:02:06.976][info][gc,heap     ] GC(24) Old regions: 117->117
[06:02:06.976][info][gc,heap     ] GC(24) Archive regions: 2->2
[06:02:06.980][info][gc,heap     ] GC(24) Humongous regions: 38->33
[06:02:06.983][info][gc,metaspace] GC(24) Metaspace: 126433K(127552K)->126433K(127552K) NonClass: 110590K(111104K)->110590K(111104K) Class: 15842K(16448K)->15842K(16448K)
[06:02:06.985][info][gc          ] GC(24) Pause Young (Normal) (G1 Evacuation Pause) 511M->187M(594M) 162.976ms
[06:02:06.985][info][gc,cpu      ] GC(24) User=0.24s Sys=0.19s Real=0.16s
[06:02:07.219][info][gc,start    ] GC(25) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[06:02:07.220][info][gc,task     ] GC(25) Using 6 workers of 6 for evacuation
[06:02:07.427][info][gc,mmu      ] GC(25) MMU target violated: 201.0ms (200.0ms/201.0ms)
[06:02:07.428][info][gc,phases   ] GC(25)   Pre Evacuate Collection Set: 0.3ms
[06:02:07.430][info][gc,phases   ] GC(25)   Merge Heap Roots: 1.0ms
[06:02:07.430][info][gc,phases   ] GC(25)   Evacuate Collection Set: 197.2ms
[06:02:07.431][info][gc,phases   ] GC(25)   Post Evacuate Collection Set: 6.4ms
[06:02:07.433][info][gc,phases   ] GC(25)   Other: 4.2ms
[06:02:07.433][info][gc,heap     ] GC(25) Eden regions: 122->0(5)
[06:02:07.434][info][gc,heap     ] GC(25) Survivor regions: 37->24(24)
[06:02:07.435][info][gc,heap     ] GC(25) Old regions: 117->250
[06:02:07.436][info][gc,heap     ] GC(25) Archive regions: 2->2
[06:02:07.436][info][gc,heap     ] GC(25) Humongous regions: 120->120
[06:02:07.441][info][gc,metaspace] GC(25) Metaspace: 126443K(127552K)->126443K(127552K) NonClass: 110600K(111104K)->110600K(111104K) Class: 15843K(16448K)->15843K(16448K)
[06:02:07.445][info][gc          ] GC(25) Pause Young (Concurrent Start) (G1 Humongous Allocation) 395M->394M(594M) 225.136ms
[06:02:07.445][info][gc,cpu      ] GC(25) User=0.69s Sys=0.29s Real=0.22s
[06:02:07.446][info][gc          ] GC(26) Concurrent Mark Cycle
[06:02:07.447][info][gc,marking  ] GC(26) Concurrent Clear Claimed Marks
[06:02:07.448][info][gc,marking  ] GC(26) Concurrent Clear Claimed Marks 0.986ms
[06:02:07.455][info][gc,marking  ] GC(26) Concurrent Scan Root Regions
[06:02:07.532][info][gc,marking  ] GC(26) Concurrent Scan Root Regions 77.048ms
[06:02:07.533][info][gc,marking  ] GC(26) Concurrent Mark
[06:02:07.532][info][gc,start    ] GC(27) Pause Young (Normal) (G1 Evacuation Pause)
[06:02:07.534][info][gc,marking  ] GC(26) Concurrent Mark From Roots
[06:02:07.534][info][gc,task     ] GC(27) Using 6 workers of 6 for evacuation
[06:02:07.535][info][gc,task     ] GC(26) Using 2 workers of 2 for marking
[06:02:07.594][info][gc,phases   ] GC(27)   Pre Evacuate Collection Set: 1.5ms
[06:02:07.594][info][gc,phases   ] GC(27)   Merge Heap Roots: 0.6ms
[06:02:07.594][info][gc,phases   ] GC(27)   Evacuate Collection Set: 51.6ms
[06:02:07.595][info][gc,phases   ] GC(27)   Post Evacuate Collection Set: 4.1ms
[06:02:07.595][info][gc,phases   ] GC(27)   Other: 5.1ms
[06:02:07.596][info][gc,heap     ] GC(27) Eden regions: 5->0(25)
[06:02:07.596][info][gc,heap     ] GC(27) Survivor regions: 24->4(4)
[06:02:07.597][info][gc,heap     ] GC(27) Old regions: 250->278
[06:02:07.597][info][gc,heap     ] GC(27) Archive regions: 2->2
[06:02:07.597][info][gc,heap     ] GC(27) Humongous regions: 173->173
[06:02:07.598][info][gc,metaspace] GC(27) Metaspace: 126444K(127552K)->126444K(127552K) NonClass: 110601K(111104K)->110601K(111104K) Class: 15843K(16448K)->15843K(16448K)
[06:02:07.598][info][gc          ] GC(27) Pause Young (Normal) (G1 Evacuation Pause) 452M->455M(594M) 66.643ms
[06:02:07.599][info][gc,cpu      ] GC(27) User=0.19s Sys=0.09s Real=0.07s
[06:02:07.626][info][gc,start    ] GC(28) Pause Young (Normal) (G1 Evacuation Pause)
[06:02:07.627][info][gc,task     ] GC(28) Using 6 workers of 6 for evacuation
[06:02:07.661][info][gc,phases   ] GC(28)   Pre Evacuate Collection Set: 0.5ms
[06:02:07.661][info][gc,phases   ] GC(28)   Merge Heap Roots: 1.6ms
[06:02:07.664][info][gc,phases   ] GC(28)   Evacuate Collection Set: 23.0ms
[06:02:07.666][info][gc,phases   ] GC(28)   Post Evacuate Collection Set: 6.4ms
[06:02:07.666][info][gc,phases   ] GC(28)   Other: 3.4ms
[06:02:07.667][info][gc,heap     ] GC(28) Eden regions: 25->0(25)
[06:02:07.668][info][gc,heap     ] GC(28) Survivor regions: 4->4(4)
[06:02:07.668][info][gc,heap     ] GC(28) Old regions: 278->303
[06:02:07.670][info][gc,heap     ] GC(28) Archive regions: 2->2
[06:02:07.670][info][gc,heap     ] GC(28) Humongous regions: 173->173
[06:02:07.672][info][gc,metaspace] GC(28) Metaspace: 126445K(127552K)->126445K(127552K) NonClass: 110602K(111104K)->110602K(111104K) Class: 15843K(16448K)->15843K(16448K)
[06:02:07.673][info][gc          ] GC(28) Pause Young (Normal) (G1 Evacuation Pause) 480M->480M(594M) 47.159ms
[06:02:07.674][info][gc,cpu      ] GC(28) User=0.10s Sys=0.04s Real=0.04s
[06:02:07.713][info][gc,start    ] GC(29) Pause Young (Normal) (G1 Evacuation Pause)
[06:02:07.716][info][gc,task     ] GC(29) Using 6 workers of 6 for evacuation
[06:02:07.761][info][gc,phases   ] GC(29)   Pre Evacuate Collection Set: 0.7ms
[06:02:07.762][info][gc,phases   ] GC(29)   Merge Heap Roots: 1.0ms
[06:02:07.763][info][gc,phases   ] GC(29)   Evacuate Collection Set: 38.6ms
[06:02:07.764][info][gc,phases   ] GC(29)   Post Evacuate Collection Set: 3.8ms
[06:02:07.764][info][gc,phases   ] GC(29)   Other: 4.1ms
[06:02:07.767][info][gc,heap     ] GC(29) Eden regions: 25->0(25)
[06:02:07.767][info][gc,heap     ] GC(29) Survivor regions: 4->4(4)
[06:02:07.768][info][gc,heap     ] GC(29) Old regions: 303->329
[06:02:07.768][info][gc,heap     ] GC(29) Archive regions: 2->2
[06:02:07.769][info][gc,heap     ] GC(29) Humongous regions: 173->173
[06:02:07.770][info][gc,metaspace] GC(29) Metaspace: 126447K(127552K)->126447K(127552K) NonClass: 110604K(111104K)->110604K(111104K) Class: 15843K(16448K)->15843K(16448K)
[06:02:07.771][info][gc          ] GC(29) Pause Young (Normal) (G1 Evacuation Pause) 505M->506M(594M) 57.670ms
[06:02:07.771][info][gc,cpu      ] GC(29) User=0.09s Sys=0.07s Real=0.06s
[06:02:07.786][info][gc,start    ] GC(30) Pause Young (Normal) (G1 Humongous Allocation)
[06:02:07.787][info][gc,task     ] GC(30) Using 6 workers of 6 for evacuation
[06:02:07.809][info][gc,phases   ] GC(30)   Pre Evacuate Collection Set: 0.6ms
[06:02:07.809][info][gc,phases   ] GC(30)   Merge Heap Roots: 1.4ms
[06:02:07.809][info][gc,phases   ] GC(30)   Evacuate Collection Set: 13.7ms
[06:02:07.810][info][gc,phases   ] GC(30)   Post Evacuate Collection Set: 3.0ms
[06:02:07.811][info][gc,phases   ] GC(30)   Other: 4.9ms
[06:02:07.811][info][gc,heap     ] GC(30) Eden regions: 16->0(25)
[06:02:07.812][info][gc,heap     ] GC(30) Survivor regions: 4->4(4)
[06:02:07.812][info][gc,heap     ] GC(30) Old regions: 329->346
[06:02:07.813][info][gc,heap     ] GC(30) Archive regions: 2->2
[06:02:07.815][info][gc,heap     ] GC(30) Humongous regions: 173->173
[06:02:07.816][info][gc,metaspace] GC(30) Metaspace: 126450K(127552K)->126450K(127552K) NonClass: 110606K(111104K)->110606K(111104K) Class: 15843K(16448K)->15843K(16448K)
[06:02:07.817][info][gc          ] GC(30) Pause Young (Normal) (G1 Humongous Allocation) 522M->523M(594M) 32.264ms
[06:02:07.819][info][gc,cpu      ] GC(30) User=0.05s Sys=0.03s Real=0.04s
[06:02:07.819][info][gc,ergo     ] Attempting full compaction
[06:02:07.821][info][gc,task     ] GC(31) Using 6 workers of 6 for full compaction
[06:02:07.822][info][gc,start    ] GC(31) Pause Full (G1 Compaction Pause)
[06:02:07.824][info][gc,phases,start] GC(31) Phase 1: Mark live objects
[06:02:08.020][info][gc,phases      ] GC(31) Phase 1: Mark live objects 196.222ms
[06:02:08.021][info][gc,phases,start] GC(31) Phase 2: Prepare for compaction
[06:02:08.038][info][gc,phases      ] GC(31) Phase 2: Prepare for compaction 16.989ms
[06:02:08.040][info][gc,phases,start] GC(31) Phase 3: Adjust pointers
[06:02:08.111][info][gc,phases      ] GC(31) Phase 3: Adjust pointers 70.781ms
[06:02:08.112][info][gc,phases,start] GC(31) Phase 4: Compact heap
[06:02:08.136][info][gc,phases      ] GC(31) Phase 4: Compact heap 24.822ms
[06:02:08.158][info][gc,heap        ] GC(31) Eden regions: 0->0(68)
[06:02:08.159][info][gc,heap        ] GC(31) Survivor regions: 4->0(4)
[06:02:08.161][info][gc,heap        ] GC(31) Old regions: 346->294
[06:02:08.163][info][gc,heap        ] GC(31) Archive regions: 2->2
[06:02:08.164][info][gc,heap        ] GC(31) Humongous regions: 173->59
[06:02:08.164][info][gc,metaspace   ] GC(31) Metaspace: 126450K(127552K)->125580K(127552K) NonClass: 110606K(111104K)->109899K(111104K) Class: 15843K(16448K)->15681K(16448K)
[06:02:08.166][info][gc             ] GC(31) Pause Full (G1 Compaction Pause) 523M->351M(594M) 343.997ms
[06:02:08.168][info][gc,cpu         ] GC(31) User=1.19s Sys=0.11s Real=0.35s
[06:02:08.169][info][gc,ergo        ] Attempting maximum full compaction clearing soft references
[06:02:08.170][info][gc,task        ] GC(32) Using 6 workers of 6 for full compaction
[06:02:08.171][info][gc,start       ] GC(32) Pause Full (G1 Compaction Pause)
[06:02:08.172][info][gc,phases,start] GC(32) Phase 1: Mark live objects
[06:02:08.382][info][gc,phases      ] GC(32) Phase 1: Mark live objects 209.907ms
[06:02:08.384][info][gc,phases,start] GC(32) Phase 2: Prepare for compaction
[06:02:08.415][info][gc,phases      ] GC(32) Phase 2: Prepare for compaction 31.599ms
[06:02:08.416][info][gc,phases,start] GC(32) Phase 3: Adjust pointers
[06:02:08.476][info][gc,phases      ] GC(32) Phase 3: Adjust pointers 59.899ms
[06:02:08.479][info][gc,phases,start] GC(32) Phase 4: Compact heap
[06:02:08.574][info][gc,phases      ] GC(32) Phase 4: Compact heap 95.300ms
[06:02:08.589][info][gc,heap        ] GC(32) Eden regions: 0->0(72)
[06:02:08.590][info][gc,heap        ] GC(32) Survivor regions: 0->0(4)
[06:02:08.592][info][gc,heap        ] GC(32) Old regions: 294->286
[06:02:08.592][info][gc,heap        ] GC(32) Archive regions: 2->2
[06:02:08.594][info][gc,heap        ] GC(32) Humongous regions: 59->59
[06:02:08.595][info][gc,metaspace   ] GC(32) Metaspace: 125580K(127552K)->124605K(127488K) NonClass: 109899K(111104K)->109098K(111040K) Class: 15681K(16448K)->15506K(16448K)
[06:02:08.596][info][gc             ] GC(32) Pause Full (G1 Compaction Pause) 351M->343M(594M) 424.729ms
[06:02:08.598][info][gc,cpu         ] GC(32) User=1.51s Sys=0.15s Real=0.43s
[06:02:08.602][info][gc,marking     ] GC(26) Concurrent Mark From Roots 1068.450ms
[06:02:08.603][info][gc,marking     ] GC(26) Concurrent Mark Abort
[06:02:08.605][info][gc             ] GC(26) Concurrent Mark Cycle 1158.585ms

Can some one please explan why this happened, why the jvm not used all the available heap space?

Answer 1

It is not possible to say why it happened with certainty. I can't see anything about the heap allocation that (I assume) triggered the OOME that killed your application.

However, if you were attempting to allocate a large object, the collector may have been unable to find enough contiguous space to allocate it. I notice that you do have a lot of homogeneous regions so there is evidence that your application has been allocating large objects.

Answer 2

Assume the following scenario: you have 1GB of heap space, currently allocated are 800 MB.

Now your code tries to execute new byte [256 * 1024 * 1024]. The gc will attempt to free some additional memory, but fails, and an OOME will be thrown, without allocating memory – there had been all time 200 MB of free memory.

You may find the offending statement in the logs, a J9 JVM will write the exact reason for the OOM to the javacore file, but the GC logs will not tell you anything in this regard.