Minor question about logging
Eugeniu Rabii
eugen.rabii at gmail.com
Mon Mar 9 14:08:43 UTC 2020
Hello Stefan,
I actually should have been more clear myself on the specific question I
have, I am sorry for that.
Comments inline.
On 3/9/20 6:41 AM, Stefan Johansson wrote:
> Hi Eugeniu,
>
> I should have been more clear around that your understanding of the
> numbers are correct. But as Thomas also responded, these are estimates
> and we might have to start a GC due to other circumstances.
>
> See more below.
>
> On 2020-03-09 11:32, Eugeniu Rabii wrote:
>> Hello Stefan,
>>
>> I know these are humongous allocations, the 2 MB was chosen on
>> purpose (I could have chose 1 MB too, I know).
>>
>> The first GC (0 - young collection) is actually the result of the
>> allocation of those humongous Objects.
>>
>> Because the humongous allocation happened, a concurrent GC was
>> triggered (GC (1)) that triggers the young collection first (GC (0));
>> these are concepts I do seem do get.
>>
>> My question here is different. After the young collection is done,
>> there are entries like this in logs:
>>
>> [0.071s][info ][gc,heap ] GC(0) Eden regions: 1->0(9)
>> [0.071s][info ][gc,heap ] GC(0) Survivor regions: 0->1(2)
>>
>> The way I read it it is: there were 1 Eden Regions before the
>> collection; everything was cleared from them (that zero) and the
>> heuristics just said that the next cycle should have 9 Eden Regions.
> Correct, but this is an estimate and we might have to GC before we
> fill up the 9 young regions. For example if there are a lot of
> humongous allocations. The humongous allocations are as I mentioned
> treated differently and aren't considered young.
>
I understand these are estimates; I also understand these could be
ignored. In fact, they are, since GC (2) is _again_ a humongous allocation.
>>
>> Same explanation would happen for Survivor Regions. As such there
>> would be : 11 young, 2 survivor.
>>
>>
>> I am expecting the third cycle (GC (2)) to start with :
>>
>>
>> [0.076s][debug][gc,heap ] GC(2) Heap before GC
>> invocations=2 (full 0): .....
>>
>> [0.076s][debug][gc,heap ] GC(2) region size 1024K, 11
>> young (2048K), 2 survivors (1024K)
>>
>>
>> Instead it prints:
>>
>>
>> [0.076s][debug][gc,heap ] GC(2) region size 1024K, 2
>> young (2048K), 1 survivors (1024K)
>>
>>
>> Does this makes it a better explanation now?
> Your expectation is correct, and if GC(2) isn't caused by a humongous
> allocation this is unexpected behavior. It would help a lot if you
> could post more of your log, especially the cause for GC(2).
Logs attached, but you are correct GC (2) is still a humongous allocation:
[0.090s][debug][gc,ergo ] Request concurrent cycle initiation
(requested by GC cause). GC cause: G1 Humongous Allocation
And now my question: what I REALLY wish for (not sure if possible) is a
log statement in GC(1) of how young regions were adjusted because of the
humongous allocation - this is the part I was missing.
I sort of already realized before posting that those are only estimates,
I hoped for some kind of a hint in logs.
>
> Thanks,
> Stefan
>
>>
>> Thank you,
>>
>> Eugene.
>>
>>
>> On 3/9/20 4:14 AM, Stefan Johansson wrote:
>>> Hi Eugeniu,
>>>
>>> The second GC is most likely also caused by having many humongous
>>> allocations. This was the cause GC(0) as well, and since your
>>> application only allocates large (humongous) objects it will not use
>>> a lot of space for other objects.
>>>
>>> If you are not familiar with the concept of humongous objects in G1,
>>> these are objects that are to large to be allocated in the normal
>>> fast path. They are instead allocated in separate regions. This
>>> requires some special handling and that's the reason we trigger GCs
>>> more quickly if a lot of such objects are allocated. In your setup
>>> the region size will be 1MB so all objects larger than 500KB will be
>>> considered humongous.
>>>
>>> Hope this helps,
>>> StefanJ
>>>
>>>
>>> On 2020-03-08 06:01, Eugeniu Rabii wrote:
>>>> Hello,
>>>>
>>>> I have a very simple program that constantly allocates some byte
>>>> arrays (of 2 MB) each (running with the latest jdk-13). I run it
>>>> with :
>>>>
>>>> -Xms20M
>>>> -Xmx20M
>>>> -Xmn10M
>>>> "-Xlog:heap*=debug" "-Xlog:gc*=debug" "-Xlog:ergo*=debug"
>>>>
>>>>
>>>> For example:
>>>>
>>>> public static void main(String[] args) {
>>>> while (true) {
>>>> System.out.println(invokeMe());
>>>> }
>>>> }
>>>>
>>>> public static int invokeMe() {
>>>> int x = 1024;
>>>> int factor = 2;
>>>> byte[] allocation1 = new byte[factor * x * x];
>>>> allocation1[2] = 3;
>>>> byte[] allocation2 = new byte[factor * x * x];
>>>> byte[] allocation3 = new byte[factor * x * x];
>>>> byte[] allocation4 = new byte[factor * x * x];
>>>>
>>>> return Arrays.hashCode(allocation1) ^
>>>> Arrays.hashCode(allocation2)
>>>> ^ Arrays.hashCode(allocation3) ^
>>>> Arrays.hashCode(allocation4);
>>>> }
>>>>
>>>> In logs, I see something that is puzzling me:
>>>>
>>>>
>>>> [0.066s][debug][gc,ergo ] Request concurrent cycle initiation
>>>> (requested by GC cause). GC cause: G1 Humongous Allocation
>>>> [0.066s][debug][gc,heap ] GC(0) Heap before GC invocations=0
>>>> (full 0): garbage-first heap total 20480K, used 6908K
>>>> [0x00000007fec00000, 0x0000000800000000)
>>>> [0.066s][debug][gc,heap ] GC(0) region size 1024K, 1 young
>>>> (1024K), 0 survivors (0K)
>>>>
>>>> OK, so Heap Before: 1 young, 0 survivors.
>>>>
>>>> Then:
>>>>
>>>> [0.071s][info ][gc,heap ] GC(0) Eden regions: 1->0(9)
>>>> [0.071s][info ][gc,heap ] GC(0) Survivor regions: 0->1(2)
>>>> [0.071s][info ][gc,heap ] GC(0) Old regions: 0->0
>>>>
>>>> So the next cycle will have 9 Eden Regions and 2 Survivor ones (at
>>>> least this is how I read the source code of where this is logged)
>>>>
>>>> Then a GC(1) concurrent cycle happens:
>>>>
>>>> [0.071s][info ][gc ] GC(1) Concurrent Cycle
>>>>
>>>> And the next cycle is where I fail to understand the logging:
>>>>
>>>> [0.076s][debug][gc,heap ] GC(2) Heap before GC
>>>> invocations=2 (full 0): garbage-first heap total 20480K, used
>>>> 7148K [0x00000007fec00000, 0x0000000800000000)
>>>> [0.076s][debug][gc,heap ] GC(2) region size 1024K, 2
>>>> young (2048K), 1 survivors (1024K)
>>>>
>>>> How come 2 young, 1 survivors? When the previous cycle said 9 Eden,
>>>> 2 Survivor.
>>>>
>>>> Thank you,
>>>> Eugene.
>>>>
>>>> _______________________________________________
>>>> hotspot-gc-use mailing list
>>>> hotspot-gc-use at openjdk.java.net
>>>> https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>>
-------------- next part --------------
[0.005s][debug][ergo] ThreadLocalHandshakes enabled.
[0.011s][info ][gc,heap] Heap region size: 1M
[0.011s][debug][gc,heap] Minimum heap 20971520 Initial heap 20971520 Maximum heap 20971520
[0.011s][debug][gc ] ConcGCThreads: 3 offset 22
[0.011s][debug][gc ] ParallelGCThreads: 10
[0.011s][debug][gc ] Initialize mark stack with 4096 chunks, maximum 16384
[0.011s][debug][gc,ergo,heap] Expand the heap. requested expansion amount: 20971520B expansion amount: 20971520B
[0.011s][debug][gc,ihop ] Target occupancy update: old: 0B, new: 20971520B
[0.011s][debug][gc,ergo,refine] Initial Refinement Zones: green: 10, yellow: 30, red: 50, min yellow size: 20
[0.011s][info ][gc ] Using G1
[0.011s][info ][gc,heap,coops ] Heap address: 0x00000007fec00000, size: 20 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[0.012s][info ][gc,cds ] Mark closed archive regions in map: [0x00000007fff00000, 0x00000007fff76ff8]
[0.012s][info ][gc,cds ] Mark open archive regions in map: [0x00000007ffe00000, 0x00000007ffe47ff8]
[0.019s][debug][cds,heap ] 0x0000000800325f80 init field @ 112 = 0x00000007ffe43e60
[0.020s][info ][cds,heap ] initialize_from_archived_subgraph java.util.ImmutableCollections$MapN 0x0000000800325f80
[0.029s][debug][cds,heap ] 0x00000008002ea3b0 init field @ 116 = 0x00000007fff70040
[0.029s][info ][cds,heap ] initialize_from_archived_subgraph java.lang.Integer$IntegerCache 0x00000008002ea3b0
[0.029s][info ][gc ] Periodic GC disabled
[0.031s][debug][cds,heap ] 0x00000008002d1988 init field @ 112 = 0x00000007ffe344c8
[0.031s][info ][cds,heap ] initialize_from_archived_subgraph java.util.ImmutableCollections$SetN 0x00000008002d1988
[0.031s][debug][cds,heap ] 0x00000008002c1810 init field @ 112 = 0x00000007ffe43e40
[0.031s][info ][cds,heap ] initialize_from_archived_subgraph java.util.ImmutableCollections$ListN 0x00000008002c1810
[0.031s][debug][cds,heap ] 0x000000080029fa00 init field @ 112 = 0x00000007ffe43e18
[0.031s][info ][cds,heap ] initialize_from_archived_subgraph java.lang.module.Configuration 0x000000080029fa00
[0.032s][debug][cds,heap ] 0x00000008002d11a0 init field @ 112 = 0x00000007ffe34150
[0.032s][info ][cds,heap ] initialize_from_archived_subgraph jdk.internal.module.ArchivedModuleGraph 0x00000008002d11a0
[0.051s][debug][cds,heap ] 0x0000000800003ed0 init field @ 112 = 0x00000007fff766d0
[0.051s][info ][cds,heap ] initialize_from_archived_subgraph sun.util.locale.BaseLocale 0x0000000800003ed0
[0.061s][debug][gc,ergo,ihop ] Request concurrent cycle initiation (occupancy higher than threshold) occupancy: 8388608B allocation request: 2097168B threshold: 9437184B (45.00) source: concurrent humongous allocation
[0.061s][debug][gc,ergo ] Request concurrent cycle initiation (requested by GC cause). GC cause: G1 Humongous Allocation
[0.061s][debug][gc,heap ] GC(0) Heap before GC invocations=0 (full 0): garbage-first heap total 20480K, used 6908K [0x00000007fec00000, 0x0000000800000000)
[0.061s][debug][gc,heap ] GC(0) region size 1024K, 1 young (1024K), 0 survivors (0K)
[0.061s][debug][gc,heap ] GC(0) Metaspace used 140K, capacity 4486K, committed 4864K, reserved 1056768K
[0.061s][debug][gc,heap ] GC(0) class space used 6K, capacity 386K, committed 512K, reserved 1048576K
[0.061s][debug][gc,ergo ] GC(0) Initiate concurrent cycle (concurrent cycle initiation requested)
[0.061s][info ][gc,start ] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[0.061s][info ][gc,task ] GC(0) Using 2 workers of 10 for evacuation
[0.061s][debug][gc,tlab ] GC(0) TLAB totals: thrds: 2 refills: 3 max: 2 slow allocs: 3 max 3 waste: 53.6% gc: 336536B max: 209712B slow: 576B max: 576B fast: 0B max: 0B
[0.061s][debug][gc,age ] GC(0) Desired survivor size 1048576 bytes, new threshold 15 (max threshold 15)
[0.061s][debug][gc,alloc,region] GC(0) Mutator Allocation stats, regions: 1, wasted size: 0B ( 0.0%)
[0.067s][debug][gc,ergo ] GC(0) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 2 regions.
[0.067s][debug][gc,ref ] GC(0) Skipped phase1 of Reference Processing due to unavailable references
[0.068s][debug][gc,ref ] GC(0) Skipped phase3 of Reference Processing due to unavailable references
[0.068s][debug][gc,ergo ] GC(0) Running G1 Free Collection Set using 1 workers for collection set length 1
[0.068s][debug][gc,humongous ] GC(0) Live humongous region 0 object size 2097168 start 0x00000007fec00000 with remset 0 code roots 0 is marked 1 reclaim candidate 0 type array 1
[0.068s][debug][gc,humongous ] GC(0) Live humongous region 3 object size 2097168 start 0x00000007fef00000 with remset 0 code roots 0 is marked 1 reclaim candidate 0 type array 1
[0.068s][debug][gc,plab ] GC(0) Young PLAB allocation: allocated: 196608B, wasted: 312B, unused: 912B, used: 195384B, undo waste: 0B,
[0.068s][debug][gc,plab ] GC(0) Young other allocation: region end waste: 0B, regions filled: 1, direct allocated: 41008B, failure used: 0B, failure wasted: 0B
[0.068s][debug][gc,plab ] GC(0) Young sizing: calculated: 39072B, actual: 39072B
[0.068s][debug][gc,plab ] GC(0) Old PLAB allocation: allocated: 0B, wasted: 0B, unused: 0B, used: 0B, undo waste: 0B,
[0.068s][debug][gc,plab ] GC(0) Old other allocation: region end waste: 0B, regions filled: 0, direct allocated: 0B, failure used: 0B, failure wasted: 0B
[0.068s][debug][gc,plab ] GC(0) Old sizing: calculated: 0B, actual: 2064B
[0.068s][debug][gc,ihop ] GC(0) Basic information (value update), threshold: 9437184B (45.00), target occupancy: 20971520B, current occupancy: 7311408B, recent allocation size: 6291456B, recent allocation duration: 50.70ms, recent old gen allocation rate: 124080777.18B/s, recent marking phase length: 0.00ms
[0.068s][debug][gc,ihop ] GC(0) Adaptive IHOP information (value update), threshold: 9437184B (52.94), internal target occupancy: 17825792B, occupancy: 7311408B, additional buffer size: 10485760B, predicted old gen allocation rate: 248161554.36B/s, predicted marking phase length: 0.00ms, prediction active: false
[0.068s][debug][gc,ergo,refine ] GC(0) Updated Refinement Zones: green: 10, yellow: 30, red: 50
[0.068s][info ][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Prepare TLABs: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Choose Collection Set: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Region Register: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Clear Claimed Marks: 0.0ms
[0.068s][info ][gc,phases ] GC(0) Evacuate Collection Set: 5.9ms
[0.068s][debug][gc,phases ] GC(0) Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.3, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Scan HCC (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Update RS (ms): Min: 0.0, Avg: 2.8, Max: 5.6, Diff: 5.6, Sum: 5.6, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Processed Buffers: Min: 0, Avg: 0.5, Max: 1, Diff: 1, Sum: 1, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Scanned Cards: Min: 0, Avg: 74.0, Max: 148, Diff: 148, Sum: 148, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Claimed Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Object Copy (ms): Min: 0.0, Avg: 0.5, Max: 0.9, Diff: 0.8, Sum: 0.9, Workers: 2
[0.068s][debug][gc,phases ] GC(0) LAB Waste Min: 0, Avg: 156.0, Max: 312, Diff: 312, Sum: 312, Workers: 2
[0.068s][debug][gc,phases ] GC(0) LAB Undo Waste Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Termination (ms): Min: 0.0, Avg: 2.4, Max: 4.8, Diff: 4.8, Sum: 4.8, Workers: 2
[0.068s][debug][gc,phases ] GC(0) Termination Attempts: Min: 1, Avg: 62.0, Max: 123, Diff: 122, Sum: 124, Workers: 2
[0.068s][debug][gc,phases ] GC(0) GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.068s][debug][gc,phases ] GC(0) GC Worker Total (ms): Min: 5.8, Avg: 5.8, Max: 5.8, Diff: 0.0, Sum: 11.7, Workers: 2
[0.068s][info ][gc,phases ] GC(0) Post Evacuate Collection Set: 0.3ms
[0.068s][debug][gc,phases ] GC(0) Code Roots Fixup: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Clear Card Table: 0.1ms
[0.068s][debug][gc,phases ] GC(0) Reference Processing: 0.1ms
[0.068s][debug][gc,phases,ref ] GC(0) Reconsider SoftReferences: 0.0ms
[0.068s][debug][gc,phases,ref ] GC(0) SoftRef (ms): skipped
[0.068s][debug][gc,phases,ref ] GC(0) Notify Soft/WeakReferences: 0.0ms
[0.068s][debug][gc,phases,ref ] GC(0) SoftRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.068s][debug][gc,phases,ref ] GC(0) WeakRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.068s][debug][gc,phases,ref ] GC(0) FinalRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.068s][debug][gc,phases,ref ] GC(0) Total (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.068s][debug][gc,phases,ref ] GC(0) Notify and keep alive finalizable: 0.0ms
[0.068s][debug][gc,phases,ref ] GC(0) FinalRef (ms): skipped
[0.068s][debug][gc,phases,ref ] GC(0) Notify PhantomReferences: 0.0ms
[0.068s][debug][gc,phases,ref ] GC(0) PhantomRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.068s][debug][gc,phases,ref ] GC(0) SoftReference:
[0.068s][debug][gc,phases,ref ] GC(0) Discovered: 0
[0.068s][debug][gc,phases,ref ] GC(0) Cleared: 0
[0.068s][debug][gc,phases,ref ] GC(0) WeakReference:
[0.068s][debug][gc,phases,ref ] GC(0) Discovered: 2
[0.068s][debug][gc,phases,ref ] GC(0) Cleared: 2
[0.068s][debug][gc,phases,ref ] GC(0) FinalReference:
[0.068s][debug][gc,phases,ref ] GC(0) Discovered: 0
[0.068s][debug][gc,phases,ref ] GC(0) Cleared: 0
[0.068s][debug][gc,phases,ref ] GC(0) PhantomReference:
[0.068s][debug][gc,phases,ref ] GC(0) Discovered: 1
[0.068s][debug][gc,phases,ref ] GC(0) Cleared: 1
[0.068s][debug][gc,phases ] GC(0) Weak Processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) JVMTI weak processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Dead: 0
[0.068s][debug][gc,phases ] GC(0) Total: 0
[0.068s][debug][gc,phases ] GC(0) JFR weak processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Dead: 0
[0.068s][debug][gc,phases ] GC(0) Total: 0
[0.068s][debug][gc,phases ] GC(0) JNI weak processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Dead: 0
[0.068s][debug][gc,phases ] GC(0) Total: 0
[0.068s][debug][gc,phases ] GC(0) StringTable weak processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Dead: 0
[0.068s][debug][gc,phases ] GC(0) Total: 4
[0.068s][debug][gc,phases ] GC(0) ResolvedMethodTable weak processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Dead: 0
[0.068s][debug][gc,phases ] GC(0) Total: 0
[0.068s][debug][gc,phases ] GC(0) VM weak processing: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Dead: 0
[0.068s][debug][gc,phases ] GC(0) Total: 3
[0.068s][debug][gc,phases ] GC(0) Merge Per-Thread State: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Code Roots Purge: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Redirty Cards: 0.0ms
[0.068s][debug][gc,phases ] GC(0) DerivedPointerTable Update: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Free Collection Set: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Humongous Reclaim: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Start New Collection Set: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Resize TLABs: 0.0ms
[0.068s][debug][gc,phases ] GC(0) Expand Heap After Collection: 0.0ms
[0.068s][info ][gc,phases ] GC(0) Other: 0.5ms
[0.068s][info ][gc,heap ] GC(0) Eden regions: 1->0(9)
[0.068s][info ][gc,heap ] GC(0) Survivor regions: 0->1(2)
[0.068s][info ][gc,heap ] GC(0) Old regions: 0->0
[0.068s][info ][gc,heap ] GC(0) Archive regions: 2->2
[0.068s][info ][gc,heap ] GC(0) Humongous regions: 6->6
[0.068s][info ][gc,metaspace ] GC(0) Metaspace: 140K->140K(1056768K)
[0.068s][debug][gc,heap ] GC(0) Heap after GC invocations=1 (full 0): garbage-first heap total 20480K, used 7140K [0x00000007fec00000, 0x0000000800000000)
[0.068s][debug][gc,heap ] GC(0) region size 1024K, 1 young (1024K), 1 survivors (1024K)
[0.068s][debug][gc,heap ] GC(0) Metaspace used 140K, capacity 4486K, committed 4864K, reserved 1056768K
[0.068s][debug][gc,heap ] GC(0) class space used 6K, capacity 386K, committed 512K, reserved 1048576K
[0.068s][info ][gc ] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 7M->6M(20M) 7.230ms
[0.068s][info ][gc,cpu ] GC(0) User=0.01s Sys=0.01s Real=0.00s
[0.068s][info ][gc ] GC(1) Concurrent Cycle
[0.069s][info ][gc,marking ] GC(1) Concurrent Clear Claimed Marks
[0.069s][info ][gc,marking ] GC(1) Concurrent Clear Claimed Marks 0.010ms
[0.069s][info ][gc,marking ] GC(1) Concurrent Scan Root Regions
[0.069s][debug][gc,ergo ] GC(1) Running G1 Root Region Scan using 1 workers for 1 work units.
[0.069s][info ][gc,marking ] GC(1) Concurrent Scan Root Regions 0.387ms
[0.069s][info ][gc,marking ] GC(1) Concurrent Mark (0.069s)
[0.069s][info ][gc,marking ] GC(1) Concurrent Mark From Roots
[0.069s][info ][gc,task ] GC(1) Using 3 workers of 3 for marking
[0.070s][debug][gc,stats ] ---------------------------------------------------------------------
[0.070s][debug][gc,stats ] Marking Stats, task = 0, calls = 1
[0.070s][debug][gc,stats ] Elapsed time = 0.87ms, Termination time = 0.01ms
[0.070s][debug][gc,stats ] Step Times (cum): num = 1, avg = 0.87ms, sd = 0.00ms max = 0.87ms, total = 0.87ms
[0.070s][debug][gc,stats ] Mark Stats Cache: hits 5641 misses 2 ratio 99.965
[0.070s][debug][gc,stats ] ---------------------------------------------------------------------
[0.070s][debug][gc,stats ] Marking Stats, task = 1, calls = 14
[0.070s][debug][gc,stats ] Elapsed time = 0.88ms, Termination time = 0.40ms
[0.070s][debug][gc,stats ] Step Times (cum): num = 14, avg = 0.06ms, sd = 0.07ms max = 0.24ms, total = 0.88ms
[0.070s][debug][gc,stats ] Mark Stats Cache: hits 1427 misses 3 ratio 99.790
[0.070s][debug][gc,stats ] ---------------------------------------------------------------------
[0.070s][debug][gc,stats ] Marking Stats, task = 2, calls = 12
[0.070s][debug][gc,stats ] Elapsed time = 0.86ms, Termination time = 0.30ms
[0.070s][debug][gc,stats ] Step Times (cum): num = 12, avg = 0.07ms, sd = 0.09ms max = 0.28ms, total = 0.86ms
[0.070s][debug][gc,stats ] Mark Stats Cache: hits 1122 misses 1 ratio 99.911
[0.070s][debug][gc,stats ] ---------------------------------------------------------------------
[0.070s][info ][gc,marking ] GC(1) Concurrent Mark From Roots 1.335ms
[0.070s][info ][gc,marking ] GC(1) Concurrent Preclean
[0.070s][debug][gc,ref,start ] GC(1) Preclean SoftReferences
[0.070s][debug][gc,ref ] GC(1) Preclean SoftReferences 0.024ms
[0.070s][debug][gc,ref,start ] GC(1) Preclean WeakReferences
[0.070s][debug][gc,ref ] GC(1) Preclean WeakReferences 0.013ms
[0.070s][debug][gc,ref,start ] GC(1) Preclean FinalReferences
[0.070s][debug][gc,ref ] GC(1) Preclean FinalReferences 0.010ms
[0.070s][debug][gc,ref,start ] GC(1) Preclean PhantomReferences
[0.070s][debug][gc,ref ] GC(1) Preclean PhantomReferences 0.010ms
[0.070s][info ][gc,marking ] GC(1) Concurrent Preclean 0.097ms
[0.070s][info ][gc,marking ] GC(1) Concurrent Mark (0.069s, 0.070s) 1.465ms
[0.072s][info ][gc,start ] GC(1) Pause Remark
[0.072s][debug][gc,phases,start] GC(1) Finalize Marking
[0.072s][debug][gc,stats ] ---------------------------------------------------------------------
[0.072s][debug][gc,stats ] Marking Stats, task = 0, calls = 42
[0.072s][debug][gc,stats ] Elapsed time = 0.03ms, Termination time = 0.02ms
[0.072s][debug][gc,stats ] Step Times (cum): num = 42, avg = 0.02ms, sd = 0.13ms max = 0.87ms, total = 0.91ms
[0.072s][debug][gc,stats ] Mark Stats Cache: hits 5641 misses 2 ratio 99.965
[0.072s][debug][gc,stats ] ---------------------------------------------------------------------
[0.072s][debug][gc,stats ] Marking Stats, task = 1, calls = 15
[0.072s][debug][gc,stats ] Elapsed time = 0.03ms, Termination time = 0.41ms
[0.072s][debug][gc,stats ] Step Times (cum): num = 15, avg = 0.06ms, sd = 0.07ms max = 0.24ms, total = 0.90ms
[0.072s][debug][gc,stats ] Mark Stats Cache: hits 1427 misses 3 ratio 99.790
[0.072s][debug][gc,stats ] ---------------------------------------------------------------------
[0.072s][debug][gc,phases ] GC(1) Finalize Marking 0.165ms
[0.072s][debug][gc,phases,start] GC(1) Reference Processing
[0.072s][debug][gc,ref ] GC(1) Skipped phase1 of Reference Processing due to unavailable references
[0.072s][debug][gc,ref ] GC(1) Skipped phase2 of Reference Processing due to unavailable references
[0.072s][debug][gc,ref ] GC(1) Skipped phase3 of Reference Processing due to unavailable references
[0.072s][debug][gc,ref ] GC(1) Skipped phase4 of Reference Processing due to unavailable references
[0.072s][debug][gc,phases,ref ] GC(1) Reference Processing: 0.0ms
[0.072s][debug][gc,phases,ref ] GC(1) Reconsider SoftReferences: 0.0ms
[0.072s][debug][gc,phases,ref ] GC(1) SoftRef (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) Notify Soft/WeakReferences: 0.0ms
[0.072s][debug][gc,phases,ref ] GC(1) SoftRef (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) WeakRef (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) FinalRef (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) Total (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) Notify and keep alive finalizable: 0.0ms
[0.072s][debug][gc,phases,ref ] GC(1) FinalRef (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) Notify PhantomReferences: 0.0ms
[0.072s][debug][gc,phases,ref ] GC(1) PhantomRef (ms): skipped
[0.072s][debug][gc,phases,ref ] GC(1) SoftReference:
[0.072s][debug][gc,phases,ref ] GC(1) Discovered: 0
[0.072s][debug][gc,phases,ref ] GC(1) Cleared: 0
[0.072s][debug][gc,phases,ref ] GC(1) WeakReference:
[0.072s][debug][gc,phases,ref ] GC(1) Discovered: 0
[0.072s][debug][gc,phases,ref ] GC(1) Cleared: 0
[0.072s][debug][gc,phases,ref ] GC(1) FinalReference:
[0.072s][debug][gc,phases,ref ] GC(1) Discovered: 0
[0.072s][debug][gc,phases,ref ] GC(1) Cleared: 0
[0.072s][debug][gc,phases,ref ] GC(1) PhantomReference:
[0.072s][debug][gc,phases,ref ] GC(1) Discovered: 0
[0.072s][debug][gc,phases,ref ] GC(1) Cleared: 0
[0.072s][debug][gc,phases ] GC(1) Reference Processing 0.338ms
[0.072s][debug][gc,phases,start] GC(1) Weak Processing
[0.072s][debug][gc,phases ] GC(1) JVMTI weak processing: 0.0ms
[0.072s][debug][gc,phases ] GC(1) Dead: 0
[0.072s][debug][gc,phases ] GC(1) Total: 0
[0.072s][debug][gc,phases ] GC(1) JFR weak processing: 0.0ms
[0.072s][debug][gc,phases ] GC(1) Dead: 0
[0.072s][debug][gc,phases ] GC(1) Total: 0
[0.072s][debug][gc,phases ] GC(1) JNI weak processing: 0.0ms
[0.072s][debug][gc,phases ] GC(1) Dead: 0
[0.072s][debug][gc,phases ] GC(1) Total: 0
[0.072s][debug][gc,phases ] GC(1) StringTable weak processing: 0.0ms
[0.072s][debug][gc,phases ] GC(1) Dead: 0
[0.072s][debug][gc,phases ] GC(1) Total: 4
[0.072s][debug][gc,phases ] GC(1) ResolvedMethodTable weak processing: 0.0ms
[0.072s][debug][gc,phases ] GC(1) Dead: 0
[0.072s][debug][gc,phases ] GC(1) Total: 0
[0.072s][debug][gc,phases ] GC(1) VM weak processing: 0.0ms
[0.072s][debug][gc,phases ] GC(1) Dead: 0
[0.072s][debug][gc,phases ] GC(1) Total: 3
[0.072s][debug][gc,phases ] GC(1) Weak Processing 0.139ms
[0.072s][debug][gc,phases,start] GC(1) Class Unloading
[0.072s][debug][gc,phases,start] GC(1) ClassLoaderData
[0.072s][debug][gc,phases ] GC(1) ClassLoaderData 0.006ms
[0.072s][debug][gc,phases,start] GC(1) Trigger cleanups
[0.072s][debug][gc,phases ] GC(1) Trigger cleanups 0.029ms
[0.073s][debug][gc,phases ] GC(1) Class Unloading 0.152ms
[0.073s][debug][gc,phases,start] GC(1) Flush Task Caches
[0.073s][debug][gc,stats ] Mark stats cache hits 8190 misses 6 ratio 99.927
[0.073s][debug][gc,phases ] GC(1) Flush Task Caches 0.050ms
[0.073s][debug][gc,phases,start] GC(1) Update Remembered Set Tracking Before Rebuild
[0.073s][debug][gc,ergo ] GC(1) Running G1 Update RemSet Tracking Before Rebuild using 1 workers for 20 regions in heap
[0.073s][debug][gc,remset,tracking] GC(1) Remembered Set Tracking update regions total 20, selected 0
[0.073s][debug][gc,phases ] GC(1) Update Remembered Set Tracking Before Rebuild 0.046ms
[0.073s][debug][gc,phases,start ] GC(1) Reclaim Empty Regions
[0.073s][debug][gc,phases ] GC(1) Reclaim Empty Regions 0.020ms
[0.073s][debug][gc,phases,start ] GC(1) Purge Metaspace
[0.073s][debug][gc,phases ] GC(1) Purge Metaspace 0.007ms
[0.073s][debug][gc,phases,start ] GC(1) Report Object Count
[0.073s][debug][gc,phases ] GC(1) Report Object Count 0.006ms
[0.073s][info ][gc ] GC(1) Pause Remark 12M->12M(20M) 1.091ms
[0.073s][info ][gc,cpu ] GC(1) User=0.00s Sys=0.00s Real=0.00s
[0.073s][info ][gc,marking ] GC(1) Concurrent Rebuild Remembered Sets
[0.073s][info ][gc,marking ] GC(1) Concurrent Rebuild Remembered Sets 0.498ms
[0.073s][info ][gc,start ] GC(1) Pause Cleanup
[0.073s][debug][gc,phases,start ] GC(1) Update Remembered Set Tracking After Rebuild
[0.073s][debug][gc,phases ] GC(1) Update Remembered Set Tracking After Rebuild 0.010ms
[0.073s][debug][gc,phases,start ] GC(1) Finalize Concurrent Mark Cleanup
[0.073s][debug][gc,ergo ] GC(1) request young-only gcs (candidate old regions not available)
[0.073s][debug][gc,phases ] GC(1) Finalize Concurrent Mark Cleanup 0.047ms
[0.073s][info ][gc ] GC(1) Pause Cleanup 13M->13M(20M) 0.099ms
[0.074s][info ][gc,cpu ] GC(1) User=0.00s Sys=0.00s Real=0.00s
[0.074s][info ][gc,marking ] GC(1) Concurrent Cleanup for Next Mark
[0.074s][debug][gc,ergo ] GC(1) Running G1 Clear Bitmap with 1 workers for 1 work units.
[0.074s][info ][gc,marking ] GC(1) Concurrent Cleanup for Next Mark 0.209ms
[0.074s][info ][gc ] GC(1) Concurrent Cycle 5.297ms
991999711
[0.090s][debug][gc,ergo,ihop ] Request concurrent cycle initiation (occupancy higher than threshold) occupancy: 14680064B allocation request: 2097168B threshold: 9437184B (45.00) source: concurrent humongous allocation
[0.090s][debug][gc,ergo ] Request concurrent cycle initiation (requested by GC cause). GC cause: G1 Humongous Allocation
[0.090s][debug][gc,heap ] GC(2) Heap before GC invocations=2 (full 0): garbage-first heap total 20480K, used 13284K [0x00000007fec00000, 0x0000000800000000)
[0.090s][debug][gc,heap ] GC(2) region size 1024K, 2 young (2048K), 1 survivors (1024K)
[0.090s][debug][gc,heap ] GC(2) Metaspace used 146K, capacity 4486K, committed 4864K, reserved 1056768K
[0.090s][debug][gc,heap ] GC(2) class space used 7K, capacity 386K, committed 512K, reserved 1048576K
[0.090s][debug][gc,ergo ] GC(2) Initiate concurrent cycle (concurrent cycle initiation requested)
[0.090s][info ][gc,start ] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[0.090s][info ][gc,task ] GC(2) Using 2 workers of 10 for evacuation
[0.090s][debug][gc,tlab ] GC(2) TLAB totals: thrds: 1 refills: 1 max: 1 slow allocs: 1 max 1 waste: 99.4% gc: 187584B max: 187584B slow: 0B max: 0B fast: 0B max: 0B
[0.090s][debug][gc,age ] GC(2) Desired survivor size 1048576 bytes, new threshold 15 (max threshold 15)
[0.090s][debug][gc,alloc,region ] GC(2) Mutator Allocation stats, regions: 1, wasted size: 0B ( 0.0%)
[0.095s][debug][gc,ergo ] GC(2) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 3 regions.
[0.095s][debug][gc,ref ] GC(2) Skipped phase1 of Reference Processing due to unavailable references
[0.095s][debug][gc,ref ] GC(2) Skipped phase3 of Reference Processing due to unavailable references
[0.095s][debug][gc,ergo ] GC(2) Running G1 Free Collection Set using 1 workers for collection set length 2
[0.095s][debug][gc,humongous ] GC(2) Dead humongous region 0 object size 2097168 start 0x00000007fec00000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[0.095s][debug][gc,humongous ] GC(2) Dead humongous region 3 object size 2097168 start 0x00000007fef00000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[0.095s][debug][gc,humongous ] GC(2) Dead humongous region 6 object size 2097168 start 0x00000007ff200000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[0.095s][debug][gc,humongous ] GC(2) Dead humongous region 9 object size 2097168 start 0x00000007ff500000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[0.095s][debug][gc,plab ] GC(2) Young PLAB allocation: allocated: 234432B, wasted: 312B, unused: 29848B, used: 204272B, undo waste: 0B,
[0.095s][debug][gc,plab ] GC(2) Young other allocation: region end waste: 0B, regions filled: 1, direct allocated: 32800B, failure used: 0B, failure wasted: 0B
[0.095s][debug][gc,plab ] GC(2) Young sizing: calculated: 40848B, actual: 40400B
[0.095s][debug][gc,plab ] GC(2) Old PLAB allocation: allocated: 0B, wasted: 0B, unused: 0B, used: 0B, undo waste: 0B,
[0.095s][debug][gc,plab ] GC(2) Old other allocation: region end waste: 0B, regions filled: 0, direct allocated: 0B, failure used: 0B, failure wasted: 0B
[0.095s][debug][gc,plab ] GC(2) Old sizing: calculated: 0B, actual: 2064B
[0.095s][debug][gc,ihop ] GC(2) Basic information (value update), threshold: 9437184B (45.00), target occupancy: 20971520B, current occupancy: 1049568B, recent allocation size: 6291456B, recent allocation duration: 21.57ms, recent old gen allocation rate: 291621394.31B/s, recent marking phase length: 0.00ms
[0.095s][debug][gc,ihop ] GC(2) Adaptive IHOP information (value update), threshold: 9437184B (52.94), internal target occupancy: 17825792B, occupancy: 1049568B, additional buffer size: 10485760B, predicted old gen allocation rate: 231801164.06B/s, predicted marking phase length: 0.00ms, prediction active: false
[0.095s][debug][gc,ergo,refine ] GC(2) Updated Refinement Zones: green: 10, yellow: 30, red: 50
[0.095s][info ][gc,phases ] GC(2) Pre Evacuate Collection Set: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Prepare TLABs: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Choose Collection Set: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Region Register: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Clear Claimed Marks: 0.0ms
[0.095s][info ][gc,phases ] GC(2) Evacuate Collection Set: 4.4ms
[0.095s][debug][gc,phases ] GC(2) Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.1, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Scan HCC (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Update RS (ms): Min: 0.6, Avg: 2.3, Max: 4.0, Diff: 3.4, Sum: 4.5, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Processed Buffers: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 3, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Scanned Cards: Min: 23, Avg: 75.0, Max: 127, Diff: 104, Sum: 150, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Skipped Cards: Min: 1, Avg: 10.0, Max: 19, Diff: 18, Sum: 20, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Scan RS (ms): Min: 0.0, Avg: 1.0, Max: 2.1, Diff: 2.1, Sum: 2.1, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Scanned Cards: Min: 0, Avg: 31.0, Max: 62, Diff: 62, Sum: 62, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Claimed Cards: Min: 0, Avg: 74.0, Max: 148, Diff: 148, Sum: 148, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Object Copy (ms): Min: 0.3, Avg: 0.4, Max: 0.5, Diff: 0.2, Sum: 0.8, Workers: 2
[0.095s][debug][gc,phases ] GC(2) LAB Waste Min: 88, Avg: 156.0, Max: 224, Diff: 136, Sum: 312, Workers: 2
[0.095s][debug][gc,phases ] GC(2) LAB Undo Waste Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Termination (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2, Workers: 2
[0.095s][debug][gc,phases ] GC(2) Termination Attempts: Min: 1, Avg: 21.0, Max: 41, Diff: 40, Sum: 42, Workers: 2
[0.095s][debug][gc,phases ] GC(2) GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.095s][debug][gc,phases ] GC(2) GC Worker Total (ms): Min: 4.3, Avg: 4.3, Max: 4.4, Diff: 0.0, Sum: 8.7, Workers: 2
[0.095s][info ][gc,phases ] GC(2) Post Evacuate Collection Set: 0.2ms
[0.095s][debug][gc,phases ] GC(2) Code Roots Fixup: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Clear Card Table: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Reference Processing: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(2) Reconsider SoftReferences: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(2) SoftRef (ms): skipped
[0.095s][debug][gc,phases,ref ] GC(2) Notify Soft/WeakReferences: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(2) SoftRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(2) WeakRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(2) FinalRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(2) Total (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(2) Notify and keep alive finalizable: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(2) FinalRef (ms): skipped
[0.095s][debug][gc,phases,ref ] GC(2) Notify PhantomReferences: 0.0ms
[0.095s][debug][gc,phases,ref ] GC(2) PhantomRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[0.095s][debug][gc,phases,ref ] GC(2) SoftReference:
[0.095s][debug][gc,phases,ref ] GC(2) Discovered: 0
[0.095s][debug][gc,phases,ref ] GC(2) Cleared: 0
[0.095s][debug][gc,phases,ref ] GC(2) WeakReference:
[0.095s][debug][gc,phases,ref ] GC(2) Discovered: 2
[0.095s][debug][gc,phases,ref ] GC(2) Cleared: 2
[0.095s][debug][gc,phases,ref ] GC(2) FinalReference:
[0.095s][debug][gc,phases,ref ] GC(2) Discovered: 0
[0.095s][debug][gc,phases,ref ] GC(2) Cleared: 0
[0.095s][debug][gc,phases,ref ] GC(2) PhantomReference:
[0.095s][debug][gc,phases,ref ] GC(2) Discovered: 1
[0.095s][debug][gc,phases,ref ] GC(2) Cleared: 1
[0.095s][debug][gc,phases ] GC(2) Weak Processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) JVMTI weak processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Dead: 0
[0.095s][debug][gc,phases ] GC(2) Total: 0
[0.095s][debug][gc,phases ] GC(2) JFR weak processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Dead: 0
[0.095s][debug][gc,phases ] GC(2) Total: 0
[0.095s][debug][gc,phases ] GC(2) JNI weak processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Dead: 0
[0.095s][debug][gc,phases ] GC(2) Total: 0
[0.095s][debug][gc,phases ] GC(2) StringTable weak processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Dead: 0
[0.095s][debug][gc,phases ] GC(2) Total: 4
[0.095s][debug][gc,phases ] GC(2) ResolvedMethodTable weak processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Dead: 0
[0.095s][debug][gc,phases ] GC(2) Total: 0
[0.095s][debug][gc,phases ] GC(2) VM weak processing: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Dead: 0
[0.095s][debug][gc,phases ] GC(2) Total: 3
[0.095s][debug][gc,phases ] GC(2) Merge Per-Thread State: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Code Roots Purge: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Redirty Cards: 0.0ms
[0.095s][debug][gc,phases ] GC(2) DerivedPointerTable Update: 0.0ms
[0.095s][debug][gc,phases ] GC(2) Free Collection Set: 0.0ms
[0.096s][debug][gc,phases ] GC(2) Humongous Reclaim: 0.0ms
[0.096s][debug][gc,phases ] GC(2) Start New Collection Set: 0.0ms
[0.096s][debug][gc,phases ] GC(2) Resize TLABs: 0.0ms
[0.096s][debug][gc,phases ] GC(2) Expand Heap After Collection: 0.0ms
[0.096s][info ][gc,phases ] GC(2) Other: 0.2ms
[0.096s][info ][gc,heap ] GC(2) Eden regions: 1->0(9)
[0.096s][info ][gc,heap ] GC(2) Survivor regions: 1->1(2)
[0.096s][info ][gc,heap ] GC(2) Old regions: 0->0
[0.096s][info ][gc,heap ] GC(2) Archive regions: 2->2
[0.096s][info ][gc,heap ] GC(2) Humongous regions: 12->0
[0.096s][info ][gc,metaspace ] GC(2) Metaspace: 146K->146K(1056768K)
[0.096s][debug][gc,heap ] GC(2) Heap after GC invocations=3 (full 0): garbage-first heap total 20480K, used 1024K [0x00000007fec00000, 0x0000000800000000)
[0.096s][debug][gc,heap ] GC(2) region size 1024K, 1 young (1024K), 1 survivors (1024K)
[0.096s][debug][gc,heap ] GC(2) Metaspace used 146K, capacity 4486K, committed 4864K, reserved 1056768K
[0.096s][debug][gc,heap ] GC(2) class space used 7K, capacity 386K, committed 512K, reserved 1048576K
[0.096s][info ][gc ] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation) 13M->1M(20M) 5.215ms
[0.096s][info ][gc,cpu ] GC(2) User=0.01s Sys=0.00s Real=0.00s
More information about the hotspot-gc-use
mailing list