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@openjdk.java.net
https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
[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
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use@openjdk.java.net
https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
