outline
Interpretation of GC logs
Interpretation of GC logs
3. Simulate YGC (different scenarios of single GC and multiple GC)
4. Open the experiment option to view the detailed log information of YGC
GC log information initial marking process
GC log information mixed recycling process
GC log information: Region details and marking process details
Log information and log details
Interpretation of GC logs
(1) A set of basic parameter settings
(2) Write a simple set of Demo code for this parameter setting
(3) TLAB related running logs
(1) A set of basic parameter settings
First, there must be a basic set of parameters:
-XX:InitialHeapSize=128M -XX:MaxHeapSize=128M -XX:+UseG1GC
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest
-XX:MaxGCPauseMillis=20 -Xloggc:The size of the heap memory is set to 128M because the Region of G1 itself must be at least 1M, and there are only a few Regions in total. If it is set to a value like 10MB, it is not easy to do experiments.
The -XX:+UnlockExperimentalVMOptions parameter is an experimental option. You can only use the -XX:G1LogLevel parameter after it is turned on. -XX:G1LogLevel=finest means setting the output level of the log to the most detailed level.
(2) Write a simple set of Demo code for this parameter setting
strs = new ArrayList();
public static void main(String[] args) throws Exception {
for (int n = 0 ;; n++) {
//Outer loop 100 times, each inner loop creates 10 strings
for (int i = 0; i<100; i++) {
//Inner loop 10 times
for (int j = 0; j < 10; j++) {
(new String("NO." + j + "Str" ));
}
}
//Infinite loop, each loop interval is 0.1s
("th" + n + "th loop");
(100);
}
}
} The meaning of this code is: infinite loop to create a string and put it into a list. Each loop will perform the operation of creating a string and adding the string to the list 1000 times. Through this code, look at the GC log information related to TLAB.
(3) TLAB related running logs
//This part is some parameter information we set
CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB -XX: +UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
2.236: [GC pause (G1 Evacuation Pause) (young)
TLAB: gc thread: 0x00000000181fd800 [id: 8648] desired_size: 122KB slow allocs: 0 refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste 1.4% gc: 1704B slow: 0B fast: 0B
TLAB: gc thread: 0x00000000181fa000 [id: 3280] desired_size: 122KB slow allocs: 2 refill waste: 1960B alloc: 0.99996 6144KB refills: 3 waste 25.0% gc: 91168B slow: 3104B fast: 0B
TLAB: gc thread: 0x00000000181bb000 [id: 10280] desired_size: 122KB slow allocs: 2 refill waste: 1960B alloc: 0.99996 6144KB refills: 7 waste 2.0% gc: 13992B slow: 3624B fast: 0B
TLAB: gc thread: 0x0000000003683800 [id: 12164] desired_size: 122KB slow allocs: 6 refill waste: 1960B alloc: 0.99996 6144KB refills: 41 waste 0.1% gc: 0B slow: 7584B fast: 0B
TLAB totals: thrds: 4 refills: 52 max: 41 slow allocs: 10 max 6 waste: 1.9% gc: 106864B max: 91168B slow: 14312B max: 7584B fast: 0B max: 0B, 0.0025449 secs]
//This part is some parameter information we set
CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB -XX: +UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
//The GC pause below is our pause time, and the young following it refers to the new generation.
2.236: [GC pause (G1 Evacuation Pause) (young)
//This large section following TLAB has several key points that we need to pay attention to.
TLAB: gc thread: 0x00000000181fd800 [id: 8648] desired_size: 122KB slow allocs: 0 refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste 1.4% gc: 1704B slow: 0B fast: 0Bgc thread: Indicates which thread's TLAB it is.
desired_size: 122KB refers to the size of the TLAB expected to be allocated. This value is actually the value calculated when we explained the TLAB calculation formula earlier. TLABSize = Eden * 2 * 1% / number of threads.
slow allocs: 0, refers to the number of slow allocations. 0 indicates that TLAB fast allocation is used every time, and heap memory is not directly used for allocation. Note that slow TLAB allocations are also considered fast allocations.
refill waste: 1960B, represents wasteful memory and is also the threshold for re-applying for a TLAB.
alloc: 0.99996, indicating the proportion of objects allocated by this thread in a partition and the proportion used by Region.
refills: 1, represents the number of times the TLAB has been abandoned and the number of times a TLAB has been reapplied. The number of refills is 1, which means that only one TLAB application has been made. Each time a TLAB is discarded, a dummy object is populated. Note: The number of refills is the number of times TLAB is filled, which can be understood as the number of times you apply for new TLAB.
waste 1.4% gc: 1704B slow: 0B fast: 0B, waste represents wasted space. This wasted space is divided into three levels:
1. gc means: The TLAB space that has not been used during GC is now in the GC state. How much space is left in TLAB that is not used.
2. Slow means: when applying for a new TLAB, the old TLAB wastes space. This is 0B because it was only generated once.
3. fast means: When the size of TLAB needs to be adjusted, that is, when refill_waste is unreasonable, the space wasted by the old TLAB is the waste caused by dummy objects.
2.236: [GC pause (G1 Evacuation Pause) (young)TLAB: gc thread: 0x00000000181fd800 [id: 8648] desired_size: 122KB slow allocs: 0 refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste 1.4% gc: 1704B slow: 0B fast: 0B Observing this TLAB status, the number of refills is still very useful. The number of refills can help us adjust the settings of TLAB related parameters and help optimize performance.
For example, after stress testing and GC logs, it was found that when the TLAB size is set to 1/4 RegionSize, fewer TLAB dynamic adjustments will occur, and this value can ensure that most objects can be directly allocated by TLAB. Then you can manually set the size of TLAB without using the value automatically inferred by G1 to avoid dynamic adjustment. Because automatic adjustment comes at a cost, each automatic adjustment will cause a certain performance loss.
Interpretation of GC logs
(1) Parameter setting
(2) Use the simple Demo code
(3) Code and YGC timing analysis
(4)YGC related operation logs
(1) Parameter setting
For YGC, we just want to simulate the entire process of YGC. And we need to print out some GC details of the entire YGC process, so we set up such a set of parameters:
-Xmx256M -XX:+UseG1GC
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
-XX:MaxGCPauseMillis=20 -Xloggc:(2) Use the simple Demo code
strs = new ArrayList();
public static void main(String[] args) throws Exception {
for (int n = 0 ;; n++) {
//Outer loop 100 times, each inner loop creates 10 strings
for (int i = 0; i<100; i++) {
//Inner loop 10 times
for (int j = 0; j < 10; j++) {
(new String("NO." + j + "Str" ));
}
}
//Infinite loop, each loop interval is 0.1s
("th" + n + "th loop");
(100);
}
}
} (3) Code and YGC timing analysis
First of all, when running this code, there is no setting on how much space the new generation will occupy before YGC occurs, so it is temporarily uncertain when YGC will occur.
But you can simply think about the timing of YGC, especially the first time. The first time YGC occurs, it should be when 256M * 5% of the new generation is used. It is approximately this value. Of course, the actual value may be slightly smaller than this value. Because there are no surviving objects in the Survivor area during the first GC of the new generation, and part of the heap memory will be occupied by other description information, so not all of the 256M heap memory will be used to allocate objects. After the program runs for a period of time: a large number of string objects will fill the Eden area, and a YGC will be triggered at this time.
(4)YGC related operation logs
As you can see, the GC log of G1 looks very complicated, with very complicated processing steps in the middle. For example, roots scanning, RS scanning and other operations. Each step of the operation will have its own time-consuming time. Next, analyze this log step by step.
//This part is some parameter information we set
CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+ UseG1GC -XX:-UseLargePagesIndividualAllocation
//From here on, the first GC occurs, probably 6.193s after the program starts, and the pause time is 0.0048641 seconds, which is about 4.8ms;
6.193: [GC pause (G1 Evacuation Pause) (young), 0.0048641 secs]
//It is obvious here that the parallel working time of GC threads is 2.9ms, and 8 GCWorkers threads are used;
//Because the computer has 8 cores at this time, different computers will have different results, because the value of the number of GCParallelThreads threads of the GC is not set;
[Parallel Time: 2.9 ms, GC Workers: 8]
//These are some time-consuming situations of thread startup, GC Roots scanning, RSet scanning, object copying and other operations;
[GC Worker Start (ms): Min: 6192.9, Avg: 6193.1, Max: 6193.6, Diff: 0.7]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 1.9, Avg: 2.2, Max: 2.3, Diff: 0.4, Sum: 17.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 16, Avg: 20.3, Max: 24, Diff: 8, Sum: 162]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 1.9, Avg: 2.5, Max: 2.6, Diff: 0.7, Sum: 19.9]
[GC Worker End (ms): Min: 6195.5, Avg: 6195.5, Max: 6195.6, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.9 ms]
[Other: 1.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
//Update card table
[Redirty Cards: 0.5 ms]
//Operation time related to large objects
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
//After the first GC, the Eden area changed dynamically from using 12M to using 0M, from a total size of 12M to a total size of 10M;
//Survivor area changed from 0 to 2048K, that is, 2048K objects survived after this GC;
//Heap memory usage has dropped from 12M to 4424K, which shows that the effect of this recycling is still good. Basically, more than 90% of the garbage has been recycled;
[Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->4424.0K(254.0M)]
[Times: user=0.00 sys=0.00, real=0.01 secs]
//The timing of the second GC. For the second GC, focus on the size of Eden Survivor to see if it has changed;
17.261: [GC pause (G1 Evacuation Pause) (young), 0.0087213 secs]
[Parallel Time: 7.7 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 17261.5, Avg: 17261.5, Max: 17261.6, Diff: 0.2]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
[Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.9, Diff: 2.9, Sum: 7.8]
[Processed Buffers: Min: 0, Avg: 1.3, Max: 3, Diff: 3, Sum: 10]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[Object Copy (ms): Min: 4.6, Avg: 6.5, Max: 7.5, Diff: 2.9, Sum: 51.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[Termination Attempts: Min: 1, Avg: 2.6, Max: 5, Diff: 4, Sum: 21]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 7.5, Avg: 7.6, Max: 7.7, Diff: 0.1, Sum: 61.1]
[GC Worker End (ms): Min: 17269.1, Avg: 17269.1, Max: 17269.1, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
//No changes to the new generation are found here, indicating that no adjustments to the new generation have been made at this time;
//But there is a phenomenon. The new generation usage has dropped from 10MB to 2048K, and the heap memory has dropped from 14.9 to 12.9;
//In other words, only about 2M objects were recycled this time, so some objects must have entered the old generation partition;
[Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 14.9M(254.0M)->12.9M(254.0M)]
[Times: user=0.09 sys=0.02, real=0.01 secs]
38.020: [GC pause (G1 Evacuation Pause) (young), 0.0101857 secs]
[Parallel Time: 8.9 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 38019.9, Avg: 38020.0, Max: 38020.1, Diff: 0.1]
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 1.3, Diff: 1.2, Sum: 2.2]
[Update RS (ms): Min: 0.0, Avg: 1.4, Max: 1.7, Diff: 1.7, Sum: 10.8]
[Processed Buffers: Min: 0, Avg: 1.9, Max: 3, Diff: 3, Sum: 15]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.7]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 6.9, Avg: 7.0, Max: 7.1, Diff: 0.2, Sum: 56.4]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 28.9, Max: 43, Diff: 42, Sum: 231]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 8.7, Avg: 8.8, Max: 8.8, Diff: 0.1, Sum: 70.3]
[GC Worker End (ms): Min: 38028.7, Avg: 38028.7, Max: 38028.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 1.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.7 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 25.2M(254.0M)->27.9M(254.0M)]
[Times: user=0.00 sys=0.00, real=0.01 secs]
58.728: [GC pause (G1 Evacuation Pause) (young), 0.0103349 secs]
[Parallel Time: 8.3 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 58727.8, Avg: 58727.9, Max: 58728.0, Diff: 0.2]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]
[Update RS (ms): Min: 0.7, Avg: 1.0, Max: 1.5, Diff: 0.8, Sum: 8.3]
[Processed Buffers: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 12]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 6.3, Avg: 6.7, Max: 6.9, Diff: 0.6, Sum: 53.7]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 11.6, Max: 19, Diff: 18, Sum: 93]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 7.8, Avg: 8.0, Max: 8.0, Diff: 0.2, Sum: 63.6]
[GC Worker End (ms): Min: 58735.8, Avg: 58735.8, Max: 58735.8, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 1.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.7 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 40.0M(254.0M)->42.0M(254.0M)]
[Times: user=0.00 sys=0.00, real=0.01 secs]Judging from the results of multiple GCs, the situation of the new generation GC is relatively stable, and the duration of each time is about 1ms (except for the first time, which is longer), and because our code does not have the operation of setting the object to null , so basically all objects can survive and be promoted to the old generation.
3. Simulate YGC (different scenarios of single GC and multiple GC)
(1) Parameter setting
(2)Simulation code
(3) GC logs related to code execution
(4) Next, modify the code
(5)Observe GC logs
(1) Parameter setting
It is still such a set of parameter structures, mainly to make some comparisons with the previous ones to see whether the simulated GC scenario is in line with the previous interpretation of the logs.
-Xmx256M -XX:+UseG1GC
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
-XX:MaxGCPauseMillis=20 -Xloggc:(2)Simulation code
public class YGCDemo1 {
//5% * 256 = Around 12M is the time when YGC occurs for the first time
//Because the heap memory 256M / 2048 is less than 1, according to the processing of G1, a Region will be set to 1M
public static void main(String[] args) throws Exception {
//The reason for setting an object to 256K. If it is too large, large object allocation will be used directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 256];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 256];
}
data = new byte[1024 * 256];
}
}Let’s analyze the code:
1. First, the first paragraph creates a data byte array, the size is 1024 * 256 = 256K
Because if the object exceeds half the Region size, it will definitely be stored separately as a large object, so the size of this object needs to be set more reasonably.
For this set of parameters, the heap memory is 256M. It is not difficult to find through calculation that the size of Region is 1M. Because 256 / 2048 is obviously smaller than 1M, it will be automatically adjusted to the size of 1M. The objects created in the code are set to 256K, and they can be allocated to the new generation Region normally.
2. Then use a loop to continuously create new arrays in the loop
And the number of loops is set to 36. Why is it set to 36? The reason is: G1 will initialize the size of the new generation when it starts. The size of the new generation accounts for 5% of the total space, which is 256M * 5%, which is approximately equal to 12M. In other words, when the application uses about 12 Regions, the first YGC will be triggered.
3. After triggering YGC
At this time, the data variable is still there, so there will still be a 256K byte array surviving, plus some unknown objects existing in the heap memory may also survive. Then after the first recycling, less than 1M objects should survive and enter the Survivor area.
(3) GC logs related to code execution
//These are the startup parameters we set, among which we need to pay attention to the maximum pause time and the size of the heap memory;
CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+ UseG1GC -XX:-UseLargePagesIndividualAllocation
//Look at the content here next. There are still 8 GC threads. The pause time caused by this GC is 0.00178, which is obviously within 20ms;
0.155: [GC pause (G1 Evacuation Pause) (young), 0.0017840 secs] [Parallel Time: 1.1 ms, GC Workers: 8]
//From this log, it can be seen that before GC, the Eden area used 12MB of memory, which is 12 Regions;
//After this GC, the Survivor usage increased from 0 before the GC started to 2048K, that is, the Survivor used 2 Regions.
//Note, this does not mean that there are so many objects in S area, but that S area uses a total of 2 Regions;
//Heap memory usage changed from 12M to 1120K, about 1M
[Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->1120.0K(254.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The final usage status of the heap memory is like this, a total of 256MB, about 3MB is used, the region size is 1MB, 5 regions are given to the new generation, and two regions are given to the survivor
Heap
garbage-first heap total 260096K, used 3168K [0x00000000f0000000, 0x00000000f01007f0, 0x0000000100000000)
region size 1024K, 5 young (5120K), 2 survivors (2048K)
Metaspace used 3451K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 376K, capacity 388K, committed 512K, reserved 1048576K(4) Next, modify the code
strs = new ArrayList();
//5% * 256 = about 12M
//Because 256M / 2048 is less than 1, according to G1 processing, a Region will be set to 1M;
public static void main(String[] args) throws Exception {
//Set an object to 256K. If it is too large, large object allocation will be performed directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 256];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 256];
}
//Create n objects and add them to a list without recycling these arrays;
ArrayList list = new ArrayList();
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 3 == 0) {
(data2);
}
}
}
} This code can trigger YGC twice, because some surviving objects will be retained in the code, so the usage of the Region will change during the second GC.
//Create n objects and add them to a list without recycling these arrays;
ArrayList list = new ArrayList();
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 3 == 0) {
(data2);
}
}The above is where the code changes. We add a loop, and every three arrays will be added to the list and will not be recycled.
(5)Observe GC logs
CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
0.150: [GC pause (G1 Evacuation Pause) (young), 0.0018467 secs]
[Parallel Time: 1.1 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 149.9, Avg: 150.1, Max: 150.9, Diff: 0.9]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 3.9]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
[Termination Attempts: Min: 1, Avg: 7.4, Max: 12, Diff: 11, Sum: 59]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 0.0, Avg: 0.8, Max: 1.0, Diff: 0.9, Sum: 6.4]
[GC Worker End (ms): Min: 150.9, Avg: 150.9, Max: 150.9, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->1120.0K(254.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.153: [GC pause (G1 Evacuation Pause) (young), 0.0014333 secs]
[Parallel Time: 1.0 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 152.9, Avg: 152.9, Max: 153.2, Diff: 0.3]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.1, Sum: 5.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.9, Max: 4, Diff: 3, Sum: 15]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 0.6, Avg: 0.8, Max: 0.9, Diff: 0.3, Sum: 6.4]
[GC Worker End (ms): Min: 153.7, Avg: 153.7, Max: 153.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 11.1M(254.0M)->3666.5K(254.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
garbage-first heap total 260096K, used 7762K [0x00000000f0000000, 0x00000000f01007f0, 0x0000000100000000)
region size 1024K, 7 young (7168K), 2 survivors (2048K)
Metaspace used 3451K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 376K, capacity 388K, committed 512K, reserved 1048576K It is obvious that two GCs occurred, and the number of Regions in the Eden area did not change after the two GCs.
4. Open the experiment option to view the detailed log information of YGC
(1) Parameter setting
(2)Simulation code
(3) GC logs related to code execution
(4)Question
(1) Parameter setting
The specific parameters are as follows:
-Xmx256M -XX:+UseG1GC
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest
-XX:MaxGCPauseMillis=20 -Xloggc:There are no special changes in parameters, mainly two parameters are added. One is to enable the experimental option, which is used to set the output level of the log. The output level of the log is set to -XX:G1LogLevel=finest
(2)Simulation code
public class YGCDemo1FinestLog {
//5% * 256 = about 12M
//Because 256M / 2048 is less than 1, according to G1 processing, a Region will be set to 1M
public static void main(String[] args) throws Exception{
//Set an object to 256K. If it is too large, large object allocation will be performed directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 256];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 256];
}
//Create n objects and add them to a list without recycling these arrays
ArrayList list = new ArrayList();
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 3 == 0) {
(data2);
byte[] bigData1 = new byte[1024 * 512];
byte[] bigData2 = new byte[1024 * 1024];
}
//At random times, we clear the list directly, and some surviving objects may eventually be left behind.
//This section mainly simulates objects that may be recycled during normal operation of the program.
if (i % () * 10 == 0) {
();
}
}
}
}Next, analyze the code:
1. First, the first paragraph creates a data byte array, the size is 1024 * 256 = 256K
Because if the object exceeds the Region size, it will definitely be stored separately as a large object, so the size of the object must be set reasonably. For the set of parameters we set, the heap memory is 256M. It is not difficult to find through calculation that the size of Region is 1M. Because 256M/2048 is obviously smaller than 1M, it will be automatically adjusted to the size of 1M. Then set the object to 256K size and it can be allocated to the new generation Region normally.
2. Then use a loop to continuously create new arrays in the loop
And the number of loops is set to 36. Why is it set to 36? The reason is that the size of the new generation is initialized when G1 starts. The size of the new generation accounts for 5% of the total space, which is 256M * 5%, which is approximately equal to 12M. In other words, when the program uses up 12 Regions, the first YGC will be triggered.
3. After triggering YGC
At this time, the data variable is still there, so there will still be a 256K byte array surviving. In addition, some unknown objects existing in some heap memory may also survive, so after the first recycling, less than 1M objects should survive and enter the Survivor area.
4. Keep some surviving objects in the list
//Create n objects and add them to a list without recycling these arrays
ArrayList list = new ArrayList();
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 3 == 0) {
(data2);
byte[] bigData1 = new byte[1024 * 512];
byte[] bigData2 = new byte[1024 * 1024];
}
...
}When the code is running, this place will simulate putting some surviving objects into the array every 3 executions.
5. Immediately afterwards, randomly clean up the list to simulate the situation where garbage and surviving objects are uncertain each time it is run.
(3) GC logs related to code execution
//These contents are the startup parameters we set. What needs to be noted is the maximum pause time and the size of the heap memory;
CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockExperimentalVMOptions -XX: +UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
//Look at the content here next. There are still 8 GC threads. The pause time caused by this GC is 0.00178, which is obviously within 20ms;
0.189: [GC pause (G1 Evacuation Pause) (young), 0.0020256 secs]
[Parallel Time: 1.4 ms, GC Workers: 8]
//Note that the following line of information refers to the start time of our 8 threads. min represents the earliest starting thread time, avg represents the average starting time, max represents the latest starting time, and diff represents the time difference between the earliest and the latest. This The larger the diff, the more uneven the thread startup time is. Generally, the time in this place will not differ greatly;
[GC Worker Start (ms): 188.7 188.7 188.7 188.7 188.8 188.8 188.8 188.8
Min: 188.7, Avg: 188.7, Max: 188.8, Diff: 0.1]
//The time it takes for 8 threads to scan and process the roots (GC Roots). It can be noticed that there are many types of roots. In addition to the often mentioned Java static variables and method local variables, there are many other roots.
[Ext Root Scanning (ms): 0.3 1.2 0.2 0.0 0.2 0.2 0.2 0.2
Min: 0.0, Avg: 0.3, Max: 1.2, Diff: 1.2, Sum: 2.5]
[Thread Roots (ms): 0.0 1.2 0.1 0.0 0.0 0.0 0.1 0.0
Min: 0.0, Avg: 0.2, Max: 1.2, Diff: 1.2, Sum: 1.5]
[StringTable Roots (ms): 0.0 0.0 0.1 0.0 0.1 0.1 0.1 0.2
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CLDG Roots (ms): 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
//Update RSet operation. As mentioned before, you need to update RSet first, and then scan RSet. In fact, you can see it in this log;
//After the object reference relationship is updated, RSet must be updated through Refine thread + system program thread + DCQ
//The following shows that the GC thread time is 0.0, indicating that there is no problem with this update.
//These operations of RSet update due to reference update have been processed in advance by the Refine thread;
[Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
//Scan RSet and process surviving objects;
[Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
//This step is very critical. Object copying is to copy the surviving object to a new partition. It can be seen that copying takes a very long time;
//Note: The time consumed by object copy accounts for most of the GC time
[Object Copy (ms): 0.5 0.0 0.6 0.0 0.7 0.6 0.6 0.6
Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.8]
//Some information about GC thread shutdown
[Termination (ms): 0.4 0.0 0.4 0.4 0.4 0.4 0.4 0.4
Min: 0.0, Avg: 0.4, Max: 0.4, Diff: 0.4, Sum: 2.8]
[Termination Attempts: 3 1 12 1 16 9 11 9
Min: 1, Avg: 7.8, Max: 16, Diff: 15, Sum: 62]
//The processing time of some other work of the GC thread, usually JVM destruction to release resources
[GC Worker Other (ms): 0.0 0.1 0.1 0.9 0.1 0.1 0.0 0.0
Min: 0.0, Avg: 0.2, Max: 0.9, Diff: 0.9, Sum: 1.3]
//The overall time spent in the parallel GC process;
[GC Worker Total (ms): 1.3 1.3 1.3 1.3 1.3 1.3 1.3 1.3
Min: 1.3, Avg: 1.3, Max: 1.3, Diff: 0.1, Sum: 10.4]
[GC Worker End (ms): 190.0 190.0 190.0 190.1 190.0 190.1 190.0 190.1
Min: 190.0, Avg: 190.0, Max: 190.1, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
//Clear the card table
[Clear CT: 0.2 ms]
[Other: 0.5 ms]
//Select the Cset time. For YGC, it is usually 0 because there is no need to select it.
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
//The time it takes to reconstruct RSet
[Redirty Cards: 0.2 ms]
[Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Redirtied Cards: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
//Large object processing time
[Humongous Register: 0.0 ms]
[Humongous Total: 0]
[Humongous Candidate: 0]
//If large objects need to be recycled, how long it takes to recycle and how many large objects are recycled
[Humongous Reclaim: 0.0 ms]
[Humongous Reclaimed: 0]
//The time it takes to release the partition in CSet
[Free CSet: 0.0 ms]
[Young Free CSet: 0.0 ms]
[Non-Young Free CSet: 0.0 ms]
//After this recycling, the status of Eden area and Survivor area
[Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->1120.0K(254.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.199: [GC pause (G1 Evacuation Pause) (young), 0.0015365 secs]
[Parallel Time: 1.0 ms, GC Workers: 8]
[GC Worker Start (ms): 199.4 199.4 199.4 199.4 199.9 199.9 199.9 200.3
Min: 199.4, Avg: 199.7, Max: 200.3, Diff: 0.9]
[Ext Root Scanning (ms): 0.2 0.2 0.2 0.2 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
[Thread Roots (ms): 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[StringTable Roots (ms): 0.0 0.1 0.2 0.1 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CLDG Roots (ms): 0.2 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): 0.6 0.7 0.7 0.7 0.4 0.4 0.3 0.0
Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.7]
[Termination (ms): 0.1 0.0 0.1 0.1 0.1 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
[Termination Attempts: 1 1 5 1 4 1 1 1
Min: 1, Avg: 1.9, Max: 5, Diff: 4, Sum: 15]
[GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): 0.9 0.9 0.9 0.9 0.4 0.4 0.4 0.0
Min: 0.0, Avg: 0.6, Max: 0.9, Diff: 0.9, Sum: 4.9]
[GC Worker End (ms): 200.3 200.3 200.3 200.3 200.3 200.3 200.3 200.3
Min: 200.3, Avg: 200.3, Max: 200.3, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Redirtied Cards: 67 0 0 0 0 0 0 0
Min: 0, Avg: 8.4, Max: 67, Diff: 67, Sum: 67]
[Humongous Register: 0.0 ms]
[Humongous Total: 16]
[Humongous Candidate: 16]
[Humongous Reclaim: 0.0 ms]
[Humongous Reclaimed: 16]
[Free CSet: 0.0 ms]
[Young Free CSet: 0.0 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 23.1M(254.0M)->3357.5K(254.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The following is the usage status of the heap memory after our program ends.
Heap
garbage-first heap total 260096K, used 15133K [0x00000000f0000000, 0x00000000f01007f0, 0x0000000100000000)
region size 1024K, 7 young (7168K), 2 survivors (2048K)
Metaspace used 3465K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 377K, capacity 388K, committed 512K, reserved 1048576K(4)Question
To simulate the log output situation of YGC running all the time, modify the code and add a while loop, with the parameters unchanged:
-Xmx256M -XX:+UseG1GC
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest
-XX:MaxGCPauseMillis=20 -Xloggc:If the following code continues to run, what changes will happen to the new generation? Combining the changes in TLAB, the prediction model, the dynamic adjustment of the new generation after YGC, and the proportion of dynamic adjustment of the new generation, let’s think about what changes will happen to YGC after the program continues to run for a period of time?
//5% * 256 = about 12M
//Because 256M / 2048 is less than 1, according to G1 processing, a Region will be set to 1M
public static void main(String[] args) throws Exception {
while(true) {
//Set an object to 256K. If it is too large, large object allocation will be performed directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 256];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 256];
}
//Create n objects and add them to a list without recycling these arrays
ArrayList list = new ArrayList();
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 3 == 0) {
(data2);
byte[] bigData1 = new byte[1024 * 512];
byte[] bigData2 = new byte[1024 * 1024];
}
//Clear the list directly at random times, and some surviving objects may eventually be left behind.
//This block mainly simulates objects that may be recycled during normal operation of the program.
if (i % ()*10 == 0) {
();
}
}
}
}
GC log information initial marking process
(1) Parameter setting
(2)Simulation code
(3) GC logs related to code execution
(1) Parameter setting
The specific parameters are as follows:
-Xmx256M -XX:+UseG1GC
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
-XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=finest -XX:MaxGCPauseMillis=20 -Xloggc: There are no special changes in parameters, mainly two parameters are added. One is to enable the experimental option, which is used to set the output level of the log. The output level of the log is set to -XX:G1LogLevel=finest
(2)Simulation code
private static final ArrayList list = new ArrayList();
//5% * 256 = about 12M
//Because 256M / 2048 is less than 1, according to G1 processing, a Region will be set to 1M
public static void main(String[] args) throws Exception {
while(true) {
//Set an object to 256K. If it is too large, large object allocation will be performed directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 256];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 256];
}
//Create n objects and add them to a list without recycling these arrays
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 2 == 0) {
(data2);
byte[] bigData1 = new byte[1024 * 512];
}
}
(1000);
}
}Let’s analyze the code:
1. First, the first paragraph creates a data byte array, the size is 1024 * 256 = 256KB
Because if the object exceeds half the size of the Region, it will be stored separately as a large object, so the size of the object must be set reasonably. For the set parameters, the heap memory is 256M. It is not difficult to find through calculation that the size of Region is 1M. Because 256M / 2048 is obviously smaller than 1M, it will be automatically adjusted to the size of 1M. Then set the object to 256K size and it can be allocated to the new generation Region normally.
2. Then a loop is used, in which new arrays are continuously created.
And the number of loops is set to 36. Why is it set to 36? The reason is that the size of the new generation is initialized when G1 starts. The size of the new generation accounts for 5% of the total space, which is 256M * 5%, which is approximately equal to 12M. That is, when 12 Regions are used up, the first YGC will be triggered.
3. After triggering YGC
Since the data variable is still there, there will still be a 256K byte array surviving. In addition, some unknown objects existing in some heap memory may also survive, so after the first recycling, less than 1M objects should survive and enter the Survivor area.
4. The bigger changes are here:
//A part of the byte array is added to the list
if (i % 2 == 0) {
(data2);
byte[] bigData1 = new byte[1024 * 512];
}When the code is running, this place simulates that the surviving objects are put into the array every 2 executions. This is done to trigger Mixed GC faster, because the trigger condition for Mixed GC is that the old generation is used 45%, and the garbage cleaning process does not necessarily follow the Initial Mark.
That is, even if the initial marking process is triggered, Mixed GC will not necessarily be started. Therefore, the surviving objects in the heap memory must always grow to ensure that it will trigger Mixed GC.
(3) GC logs related to code execution
It can be seen from the following log: YGC is triggered first, and the time is not long. Then after many YGCs, the initial mark of Mixed GC will be triggered, and after the initial mark of Mixed GC is triggered, Mixed GC will not necessarily follow. Because the application will still be running during this period, it is possible to continue to trigger YGC.
0.177: [GC pause (G1 Evacuation Pause) (young), 0.0017408 secs]
// 8 threads are started for execution, and the parallel execution time is 1.2ms
[Parallel Time: 1.2 ms, GC Workers: 8]
[GC Worker Start (ms): 177.2 177.2 177.2 177.2 177.2 177.6 178.3 178.3
Min: 177.2, Avg: 177.5, Max: 178.3, Diff: 1.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
...
//It can be seen from here that this GC is a very conventional YGC. Before the GC, there was no S area. After the GC, there will be one S area next time, which is 1M space;
//Heap memory is 6144K garbage before recycling, and 1048K garbage after recycling
[Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 6144.0K(128.0M)->1048.0K(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//For the second recycling, we focus on the growth rate of the object
0.180: [GC pause (G1 Evacuation Pause) (young), 0.0016041 secs]
[Parallel Time: 1.1 ms, GC Workers: 8]
[GC Worker Start (ms): 180.3 180.3 180.3 180.3 180.3 180.3 180.6 181.2
Min: 180.3, Avg: 180.4, Max: 181.2, Diff: 1.0]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
...
//You can see it from below:
//The object growth rate is actually not fast, and the number of Eden areas has been increased by one
[Eden: 5120.0K(5120.0K)->0.0B(6144.0K) Survivors: 1024.0K->1024.0K Heap: 6168.0K(128.0M)->1427.9K(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Next, many times of ordinary YGC will be omitted. There is no need to release the YGC process because there are too many;
...
...
...
...
//At this time of YGC, it is still a very normal YGC and a regular YGC result;
7.289: [GC pause (G1 Evacuation Pause) (young), 0.0029624 secs]
[Parallel Time: 1.8 ms, GC Workers: 8]
[GC Worker Start (ms): 7288.9 7288.9 7288.9 7289.0 7289.0 7289.0 7289.0 7289.0
Min: 7288.9, Avg: 7288.9, Max: 7289.0, Diff: 0.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.5 ms]
[Other: 0.6 ms]
...
//Pay attention here, the heap memory is already used a lot at this time;
//The Eden area is 0B after recycling, the S area has been expanded to about 6M, and the total heap memory usage is 47.5M. At this time, the usage is actually relatively high;
[Eden: 38.0M(38.0M)->0.0B(57.0M) Survivors: 5120.0K->6144.0K Heap: 89.3M(128.0M)->47.5M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
// Focus here, and find that the initial mark has been turned on (it can be seen that it is still a YGC at this time);
8.309: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0014780 secs]
[Parallel Time: 1.0 ms, GC Workers: 8]
[GC Worker Start (ms): 8308.9 8308.9 8308.9 8308.9 8308.9 8308.9 8309.0 8309.1
Min: 8308.9, Avg: 8309.0, Max: 8309.1, Diff: 0.2]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.3 ms]
...
//From the data after this recycling, we can see that the 45% rule is indeed followed;
//After YGC garbage collection, when the space occupied by the objects to be allocated + all objects in the old generation reaches 45%, Mixed GC will be triggered, which means concurrent marking is turned on;
[Eden: 24.0M(57.0M)->0.0B(49.0M) Survivors: 6144.0K->6144.0K Heap: 78.8M(128.0M)->53.0M(128.0M)]
[Times: user=0.09 sys=0.00, real=0.00 secs]
//Start and end of concurrent root scan
8.311: [GC concurrent-root-region-scan-start]
8.311: [GC concurrent-root-region-scan-end, 0.0000467 secs]
//The beginning and end of concurrent marking
8.311: [GC concurrent-mark-start]
8.313: [GC concurrent-mark-end, 0.0018556 secs]
//Remark stage
8.313: [GC remark 8.313: [Finalize Marking, 0.0001905 secs] 8.313: [GC ref-proc, 0.0003040 secs] 8.313: [Unloading 8.313: [System Dictionary Unloading, 0.0000130 secs] 8.313: [Parallel Unloading, 0.0005763 secs] 8.314: [Deallocate Metadata, 0.0000144 secs], 0.0006416 secs], 0.0014267 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Pre-cleaning phase
8.314: [GC cleanup 75M->75M(128M), 0.0016325 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
// Another YGC is performed, because the concurrent marking phase after the initial marking of Mixed GC will run concurrently with the system program, so here is the YGC triggered by the system program
9.331: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0008772 secs]
[Parallel Time: 0.4 ms, GC Workers: 8]
[GC Worker Start (ms): 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0
Min: 9331.0, Avg: 9331.0, Max: 9331.0, Diff: 0.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
...
[Eden: 37.0M(49.0M)->0.0B(6144.0K) Survivors: 6144.0K->0.0B Heap: 108.5M(128.0M)->78.8M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The next step is the Mixed GC triggered by printing
10.347: [GC pause (G1 Evacuation Pause) (mixed), 0.0017163 secs]
[Parallel Time: 1.2 ms, GC Workers: 8]
[GC Worker Start (ms): 10347.3 10347.3 10347.3 10347.3 10347.3 10347.3 10347.5 10347.6
Min: 10347.3, Avg: 10347.4, Max: 10347.6, Diff: 0.3]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
...
[Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 85.3M(128.0M)->78.8M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
10.350: [GC pause (G1 Evacuation Pause) (mixed), 0.0015104 secs]
[Parallel Time: 0.8 ms, GC Workers: 8]
[GC Worker Start (ms): 10350.1 10350.2 10350.2 10350.2 10350.2 10350.2 10350.2 10350.3
Min: 10350.1, Avg: 10350.2, Max: 10350.3, Diff: 0.2]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.5 ms]
...
[Eden: 5120.0K(5120.0K)->0.0B(27.0M) Survivors: 1024.0K->1024.0K Heap: 83.8M(128.0M)->79.5M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The initial mark of Mixed GC appears again
10.353: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0009719 secs]
[Parallel Time: 0.4 ms, GC Workers: 8]
[GC Worker Start (ms): 10352.6 10352.6 10352.7 10352.7 10352.7 10352.7 10352.7 10352.7
Min: 10352.6, Avg: 10352.7, Max: 10352.7, Diff: 0.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.4 ms]
...
[Eden: 3072.0K(27.0M)->0.0B(28.0M) Survivors: 1024.0K->1024.0K Heap: 82.0M(128.0M)->79.8M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
10.354: [GC concurrent-root-region-scan-start]
10.354: [GC concurrent-root-region-scan-end, 0.0000481 secs]
10.354: [GC concurrent-mark-start]
10.356: [GC concurrent-mark-end, 0.0019111 secs]
10.356: [GC remark 10.356: [Finalize Marking, 0.0002410 secs] 10.357: [GC ref-proc, 0.0002787 secs] 10.357: [Unloading 10.357: [System Dictionary Unloading, 0.0000089 secs] 10.357: [Parallel Unloading, 0.0005675 secs] 10.357: [Deallocate Metadata, 0.0000145 secs], 0.0006318 secs], 0.0014424 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
10.358: [GC cleanup 101M->101M(128M), 0.0006501 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
GC log information mixed recycling process
Continue the previous Mixed GC log analysis:
...
//This time YGC is still a very normal YGC;
7.289: [GC pause (G1 Evacuation Pause) (young), 0.0029624 secs]
[Parallel Time: 1.8 ms, GC Workers: 8]
...
//Note that the heap memory usage is already very large at this time;
//After the Eden area is recycled, it is 0B, the S area has been expanded to about 6M, and the total heap memory usage is 47.5M. At this time, the usage is actually relatively high;
[Eden: 38.0M(38.0M)->0.0B(57.0M) Survivors: 5120.0K->6144.0K Heap: 89.3M(128.0M)->47.5M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Next here, it is found that the initial mark has been turned on;
8.309: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0014780 secs]
[Parallel Time: 1.0 ms, GC Workers: 8]
...
//The data after this recycling is shown in the next line;
//It can be seen from the data that it does follow the 45% rule;
//After garbage collection, when the space occupied by the objects to be allocated + all objects in the old generation reaches 45%, Mixed GC will be triggered, which means concurrent marking is turned on;
[Eden: 24.0M(57.0M)->0.0B(49.0M) Survivors: 6144.0K->6144.0K Heap: 78.8M(128.0M)->53.0M(128.0M)]
[Times: user=0.09 sys=0.00, real=0.00 secs]
//It can also be seen from here that the initial marking state is actually a YGC. However, it should be noted that after the initial marking, Mixed GC will not necessarily be executed.
//After the initial mark, concurrent mark will be entered;
//The following lines actually do a concurrently marked GC Roots scan starting from the Survivor partition in YHR;
//It can be understood that all surviving objects in the Survivor area are found and used as root objects. This part has not yet scanned the old generation objects directly referenced by GC Roots.
8.311: [GC concurrent-root-region-scan-start]
//Scan ends, it takes 0.0000467 seconds. What needs to be noted about this scanning process is that it is performed at the same time as the application, and multiple threads are involved.
8.311: [GC concurrent-root-region-scan-end, 0.0000467 secs]
//The full scanning process of concurrent marking is to mark all surviving objects in the entire heap with Survivor + GC Roots (local variables, static variables, etc. in the method stack)
8.311: [GC concurrent-mark-start]
//Concurrent marking ended, it took 0.0018565 seconds
8.313: [GC concurrent-mark-end, 0.0018556 secs]
//The final marking stage, the processing of new objects created by the marking program, soft references, weak references, etc.;
8.313: [GC remark 8.313: [Finalize Marking, 0.0001905 secs] 8.313: [GC ref-proc, 0.0003040 secs] 8.313: [Unloading 8.313: [System Dictionary Unloading, 0.0000130 secs] 8.313: [Parallel Unloading, 0.0005763 secs] 8.314: [Deallocate Metadata, 0.0000144 secs], 0.0006416 secs], 0.0014267 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Pre-cleaning process, this place clears the Region partitions that are all garbage. It can be seen from the log here that no Region has been cleared.
8.314: [GC cleanup 75M->75M(128M), 0.0016325 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then, YGC is entered again (at this time, the S area is insufficient and the S area needs to be cleared);
//And it is marked to-space exhausted, which means that the to area is not enough after this GC. Some operations need to be done to promote objects to the old generation and adjust the size of the S area.
9.331: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0008772 secs]
[Parallel Time: 0.4 ms, GC Workers: 8]
[GC Worker Start (ms): 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0
Min: 9331.0, Avg: 9331.0, Max: 9331.0, Diff: 0.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
...
//It can be seen here that after this recycling, the S area has become 0
[Eden: 37.0M(49.0M)->0.0B(6144.0K) Survivors: 6144.0K->0.0B Heap: 108.5M(128.0M)->78.8M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then it begins to enter the mixed recycling stage. The content of mixed recycling is actually similar to the content of YGC.
10.347: [GC pause (G1 Evacuation Pause) (mixed), 0.0017163 secs]
//Parallel time 1.2ms, 8 threads participate
[Parallel Time: 1.2 ms, GC Workers: 8]
[GC Worker Start (ms): 10347.3 10347.3 10347.3 10347.3 10347.3 10347.3 10347.5 10347.6
Min: 10347.3, Avg: 10347.4, Max: 10347.6, Diff: 0.3]
[Ext Root Scanning (ms): 0.2 0.2 0.2 0.2 0.2 0.1 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
[Thread Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[StringTable Roots (ms): 0.1 0.2 0.1 0.1 0.2 0.1 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CLDG Roots (ms): 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[Processed Buffers: 2 1 1 0 0 1 0 0
Min: 0, Avg: 0.6, Max: 2, Diff: 2, Sum: 5]
[Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): 0.8 0.9 0.9 0.8 0.8 0.8 0.8 0.7
Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.2, Sum: 6.4]
[Termination (ms): 0.1 0.1 0.0 0.1 0.1 0.1 0.1 0.1
Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]
[Termination Attempts: 1 1 1 1 1 1 1 1
Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): 1.1 1.1 1.1 1.1 1.1 1.1 0.9 0.8
Min: 0.8, Avg: 1.0, Max: 1.1, Diff: 0.3, Sum: 8.4]
[GC Worker End (ms): 10348.4 10348.4 10348.4 10348.4 10348.4 10348.4 10348.4 10348.4
Min: 10348.4, Avg: 10348.4, Max: 10348.4, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Redirtied Cards: 4 0 0 0 0 0 0 0
Min: 0, Avg: 0.5, Max: 4, Diff: 4, Sum: 4]
[Humongous Register: 0.0 ms]
[Humongous Total: 1]
[Humongous Candidate: 1]
[Humongous Reclaim: 0.0 ms]
[Humongous Reclaimed: 1]
[Free CSet: 0.0 ms]
[Young Free CSet: 0.0 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 85.3M(128.0M)->78.8M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//It can be seen from the above that the process of the recycling phase of Mixed GC is almost exactly the same as that of YGC. What is the reason?
//In fact, the code is reused, and the main difference lies in the selected Cset.
//The following is another Mixed GC, because it will be divided into batches, the default is up to 8 times
10.350: [GC pause (G1 Evacuation Pause) (mixed), 0.0015104 secs]
[Parallel Time: 0.8 ms, GC Workers: 8]
[GC Worker Start (ms): 10350.1 10350.2 10350.2 10350.2 10350.2 10350.2 10350.2 10350.3
Min: 10350.1, Avg: 10350.2, Max: 10350.3, Diff: 0.2]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.5 ms]
...
[Eden: 5120.0K(5120.0K)->0.0B(27.0M) Survivors: 1024.0K->1024.0K Heap: 83.8M(128.0M)->79.5M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The initial mark is triggered again
//In fact, seeing that the initial mark is triggered here, you can roughly guess that the subsequent Mixed GC will be very frequent, and the initial mark will also occur frequently because there are too many surviving objects in the old generation;
10.353: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0009719 secs]
[Parallel Time: 0.4 ms, GC Workers: 8]
[GC Worker Start (ms): 10352.6 10352.6 10352.7 10352.7 10352.7 10352.7 10352.7 10352.7
Min: 10352.6, Avg: 10352.7, Max: 10352.7, Diff: 0.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.4 ms]
...
[Eden: 3072.0K(27.0M)->0.0B(28.0M) Survivors: 1024.0K->1024.0K Heap: 82.0M(128.0M)->79.8M(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
10.354: [GC concurrent-root-region-scan-start]
10.354: [GC concurrent-root-region-scan-end, 0.0000481 secs]
10.354: [GC concurrent-mark-start]
10.356: [GC concurrent-mark-end, 0.0019111 secs]
10.356: [GC remark 10.356: [Finalize Marking, 0.0002410 secs] 10.357: [GC ref-proc, 0.0002787 secs] 10.357: [Unloading 10.357: [System Dictionary Unloading, 0.0000089 secs] 10.357: [Parallel Unloading, 0.0005675 secs] 10.357: [Deallocate Metadata, 0.0000145 secs], 0.0006318 secs], 0.0014424 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
10.358: [GC cleanup 101M->101M(128M), 0.0006501 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]The process of Mixed GC is relatively complicated. After the initial mark is triggered, the recycling phase of Mixed GC does not necessarily follow. It is possible that the YGC process will continue before entering the recycling phase of Mixd GC.
It can be seen that for Mixed GC: the entire process from initial marking to concurrent marking to the recycling phase is not necessarily a continuous entire process. Because the program will run during the concurrent marking phase, YGC may be triggered again. And when the recyclable garbage is less than 5%, the recycling phase of Mixed GC will not be triggered. At the same time, if after multiple GCs, it is less than this 5%, mixed recovery may not continue. Of course, this 5% is not easy to simulate. If it is an online program, it is actually better to simulate.
GC log information: Region details and marking process details
(1) Parameter setting
(2)Simulation code
(3) GC logs related to code execution
(4) What is the use of these data?
(1) Parameter setting
The specific parameters are as follows:
-Xmx128M -XX:+UseG1GC
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest
-XX:+UnlockDiagnosticVMOptions -XX:+G1PrintRegionLivenessInfo
-XX:+G1SummarizeConcMark -XX:MaxGCPauseMillis=20
-Xloggc:The differences from the JVM parameters set previously are as follows:
Turn on data analysis options: -XX:+UnlockDiagnosticVMOptions
Print usage details of all regions: -XX:+G1PrintRegionLivenessInfo
Turn on concurrent mark details: -XX:+G1SummarizeConcMark(2)Simulation code
public static void main(String[] args) throws Exception {
while(true) {
//Set an object to 256K. If it is too large, large object allocation will be performed directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 256];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 256];
}
//Create n objects and add them to a list without recycling these arrays
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 256];
//A part of the byte array is added to the list
if (i % 2 == 0) {
(data2);
byte[] bigData1 = new byte[1024 * 512];
}
}
(100);
}
}(3) GC logs related to code execution
CommandLine flags: -XX:G1LogLevel=finest -XX:+G1PrintRegionLivenessInfo -XX:+G1SummarizeConcMark -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
0.130: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0020150 secs]
[Parallel Time: 1.0 ms, GC Workers: 8]
[GC Worker Start (ms): 129.7 129.8 129.8 129.8 129.8 129.8 129.8 129.8
Min: 129.7, Avg: 129.8, Max: 129.8, Diff: 0.1]
...
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 0.7 ms]
...
[Eden: 3072.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 31.1M(128.0M)->1848.1K(128.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.132: [GC concurrent-root-region-scan-start]
0.133: [GC concurrent-root-region-scan-end, 0.0008120 secs]
0.133: [GC concurrent-mark-start]
0.133: [GC concurrent-mark-end, 0.0001406 secs]
0.133: [GC remark 0.133: [Finalize Marking, 0.0004982 secs] 0.134: [GC ref-proc, 0.0002247 secs] 0.134: [Unloading 0.134: [System Dictionary Unloading, 0.0000091 secs] 0.134: [Parallel Unloading, 0.0005040 secs] 0.134: [Deallocate Metadata, 0.0000141 secs], 0.0005701 secs], 0.0016329 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.135: [GC cleanup
### PHASE Post-Marking @ 0.135
### HEAP reserved: 0x00000000f8000000-0x0000000100000000 region-size: 1048576
### type (partition type) address-range (address range) used (usage) prev-live next-live gc-eff (GC efficiency) remset (Rset size) code-roots
### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes)
### HUMS 0x00000000f8000000-0x00000000f8100000 1048576 1048576 1048576 0.0 2904 16
### HUMC 0x00000000f8100000-0x00000000f8200000 16 16 16 0.0 2904 16
...
### HUMS 0x00000000fae00000-0x00000000faf00000 1048576 1048576 1048576 0.0 2904 16
### HUMC 0x00000000faf00000-0x00000000fb000000 16 16 16 0.0 2904 16
### FREE 0x00000000fb000000-0x00000000fb100000 0 0 0 0.0 2904 16
### FREE 0x00000000fb100000-0x00000000fb200000 0 0 0 0.0 2904 16
### FREE 0x00000000fb200000-0x00000000fb300000 0 0 0 0.0 2904 16
### FREE 0x00000000fb300000-0x00000000fb400000 0 0 0 0.0 2904 16
### FREE 0x00000000fb400000-0x00000000fb500000 0 0 0 0.0 2904 16
### FREE 0x00000000fb500000-0x00000000fb600000 0 0 0 0.0 2904 16
### FREE 0x00000000fb600000-0x00000000fb700000 0 0 0 0.0 2904 16
### FREE 0x00000000fb700000-0x00000000fb800000 0 0 0 0.0 2904 16
### HUMS 0x00000000fb800000-0x00000000fb900000 1048576 1048576 1048576 0.0 2904 16
### HUMC 0x00000000fb900000-0x00000000fba00000 16 16 16 0.0 2904 16
### FREE 0x00000000fba00000-0x00000000fbb00000 0 0 0 0.0 2904 16
...
### FREE 0x00000000ffa00000-0x00000000ffb00000 0 0 0 0.0 2904 16
### FREE 0x00000000ffb00000-0x00000000ffc00000 0 0 0 0.0 2904 16
### SURV 0x00000000ffc00000-0x00000000ffd00000 843840 843840 843840 0.0 3056 168
### FREE 0x00000000ffd00000-0x00000000ffe00000 0 0 0 0.0 2904 16
### FREE 0x00000000ffe00000-0x00000000fff00000 0 0 0 0.0 2904 16
### EDEN 0x00000000fff00000-0x0000000100000000 104904 104904 104904 0.0 2904 16
###
### SUMMARY capacity: 128.00 MB used: 25.91 MB / 20.24 % prev-live: 25.91 MB / 20.24 % next-live: 25.91 MB / 20.24 % remset: 0.36 MB code-roots: 0.00 MB
### PHASE Post-Sorting @ 0.136
### HEAP reserved: 0x00000000f8000000-0x0000000100000000 region-size: 1048576
###
### type address-range used prev-live next-live gc-eff remset code-roots
### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes)
###
### SUMMARY capacity: 0.00 MB used: 0.00 MB / 0.00 % prev-live: 0.00 MB / 0.00 % next-live: 0.00 MB / 0.00 % remset: 0.01 MB code-roots: 0.00 MB
25M->25M(128M), 0.0010444 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The usage status of the heap memory before exiting
Heap
garbage-first heap total 131072K, used 65513K [0x00000000f8000000, 0x00000000f8100400, 0x0000000100000000)
region size 1024K, 1 young (1024K), 0 survivors (0K)
Metaspace used 3969K, capacity 4568K, committed 4864K, reserved 1056768K
class space used 437K, capacity 460K, committed 512K, reserved 1048576K
//The status of concurrent marks, including mark types, such as initial mark status, init marks, concurrent mark remarks, final marks, weak refs, weak reference processing
Concurrent marking:
0 init marks: total time = 0.00 s (avg = 0.00 ms).
2 remarks: total time = 0.00 s (avg = 1.36 ms).
[std. dev = 0.00 ms, max = 1.36 ms]
2 final marks: total time = 0.00 s (avg = 0.21 ms).
[std. dev = 0.02 ms, max = 0.23 ms]
2 weak refs: total time = 0.00 s (avg = 1.14 ms).
[std. dev = 0.02 ms, max = 1.16 ms]
2 cleanups: total time = 0.00 s (avg = 0.78 ms).
[std. dev = 0.33 ms, max = 1.11 ms]
//The time spent counting objects
Final counting total time = 0.00 s (avg = 0.24 ms).
//RSet processing time
RS scrub total time = 0.00 s (avg = 0.22 ms).
//How long does it take for all STW stages to be paused in total?
Total stop_world time = 0.00 s.
//The total time spent by all GC threads in the entire concurrent marking process (multiple threads concurrently, the time consumption of each thread is summed)
Total concurrent time = 0.03 s ( 0.03 s marking).(4) What is the use of these data?
Normally, the following parameters do not need to be turned on:
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest
-XX:+UnlockDiagnosticVMOptions -XX:+G1SummarizeConcMarkBasically, problems can be found with the help of ordinary GC logs. If you want to know more about the time consumption of each stage and the recycling efficiency of each Region, you can turn on these options. For example, statistics on the time taken for each stage of concurrent marking and statistics on how the data of each Region is distributed. Based on this, adjust parameters such as pause time and RegionSize for optimization.
//Time consuming in each stage of YGC
//There are still 8 GC threads. The pause time caused by this GC is 0.00178, which is obviously within 20ms;
0.189: [GC pause (G1 Evacuation Pause) (young), 0.0020256 secs]
[Parallel Time: 1.4 ms, GC Workers: 8]
//Note that the following line of information refers to the start time of our 8 threads. min represents the earliest starting thread time, avg represents the average starting time, max represents the latest starting time, and diff represents the time difference between the earliest and the latest. This The larger the diff, the more uneven the thread startup time is. Generally, the time in this place will not differ greatly;
[GC Worker Start (ms): 188.7 188.7 188.7 188.7 188.8 188.8 188.8 188.8
Min: 188.7, Avg: 188.7, Max: 188.8, Diff: 0.1]
//8 threads scan and process the roots (GC Roots). It can be noticed that there are many types of roots. In addition to the often mentioned Java static variables and method local variables, there are many other roots.
[Ext Root Scanning (ms): 0.3 1.2 0.2 0.0 0.2 0.2 0.2 0.2
Min: 0.0, Avg: 0.3, Max: 1.2, Diff: 1.2, Sum: 2.5]
[Thread Roots (ms): 0.0 1.2 0.1 0.0 0.0 0.0 0.1 0.0
Min: 0.0, Avg: 0.2, Max: 1.2, Diff: 1.2, Sum: 1.5]
[StringTable Roots (ms): 0.0 0.0 0.1 0.0 0.1 0.1 0.1 0.2
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CLDG Roots (ms): 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
//Update RSet operation. As mentioned before, you need to update RSet first, and then scan RSet. In fact, you can see it in this log;
//After the object reference relationship is updated, RSet must be updated through Refine thread + system program thread + DCQ
//The following shows that the GC thread time is 0.0, indicating that there is no problem with this update.
//These operations of RSet update due to reference update have been processed in advance by the Refine thread;
[Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
//Scan RSet and process surviving objects;
[Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
//This step is very critical. Object copying is to copy the surviving object to a new partition. It can be seen that copying takes a very long time;
//Note: The time consumed by object copy accounts for most of the GC time
[Object Copy (ms): 0.5 0.0 0.6 0.0 0.7 0.6 0.6 0.6
Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.8]
//Some information about GC thread shutdown
[Termination (ms): 0.4 0.0 0.4 0.4 0.4 0.4 0.4 0.4
Min: 0.0, Avg: 0.4, Max: 0.4, Diff: 0.4, Sum: 2.8]
[Termination Attempts: 3 1 12 1 16 9 11 9
Min: 1, Avg: 7.8, Max: 16, Diff: 15, Sum: 62]
//The processing time of some other work of the GC thread, usually JVM destruction to release resources
[GC Worker Other (ms): 0.0 0.1 0.1 0.9 0.1 0.1 0.0 0.0
Min: 0.0, Avg: 0.2, Max: 0.9, Diff: 0.9, Sum: 1.3]
//The overall time spent in the parallel GC process;
[GC Worker Total (ms): 1.3 1.3 1.3 1.3 1.3 1.3 1.3 1.3
Min: 1.3, Avg: 1.3, Max: 1.3, Diff: 0.1, Sum: 10.4]
[GC Worker End (ms): 190.0 190.0 190.0 190.1 190.0 190.1 190.0 190.1
Min: 190.0, Avg: 190.0, Max: 190.1, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
//Clear the card table
[Clear CT: 0.2 ms]
[Other: 0.5 ms]
//Select the Cset time. For YGC, it is usually 0 because there is no need to select it.
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
//The time it takes to reconstruct RSet
[Redirty Cards: 0.2 ms]
[Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Redirtied Cards: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
//Large object processing time
[Humongous Register: 0.0 ms]
[Humongous Total: 0]
[Humongous Candidate: 0]
//If large objects need to be recycled, how long it takes to recycle and how many large objects are recycled
[Humongous Reclaim: 0.0 ms]
[Humongous Reclaimed: 0]
//The time it takes to release the partition in CSet
[Free CSet: 0.0 ms]
[Young Free CSet: 0.0 ms]
[Non-Young Free CSet: 0.0 ms]
//Mixed GC takes time in each stage
//After the initial mark, concurrent mark will be entered;
//The following lines actually do a concurrently marked GC Roots scan starting from the Survivor partition in YHR;
//It can be understood that all surviving objects in the Survivor area are found and used as root objects. This part has not yet scanned the old generation objects directly referenced by GC Roots.
8.311: [GC concurrent-root-region-scan-start]
//Scan ends, it takes 0.0000467 seconds. What needs to be noted about this scanning process is that it is performed at the same time as the application, and multiple threads are involved.
8.311: [GC concurrent-root-region-scan-end, 0.0000467 secs]
//The full scanning process of concurrent marking is to mark all surviving objects in the entire heap with Survivor + GC Roots (local variables, static variables, etc. in the method stack)
8.311: [GC concurrent-mark-start]
//Concurrent marking ended, it took 0.0018565 seconds
8.313: [GC concurrent-mark-end, 0.0018556 secs]
//The final marking stage, the processing of new objects created by the marking program, soft references, weak references, etc.;
8.313: [GC remark 8.313: [Finalize Marking, 0.0001905 secs] 8.313: [GC ref-proc, 0.0003040 secs] 8.313: [Unloading 8.313: [System Dictionary Unloading, 0.0000130 secs] 8.313: [Parallel Unloading, 0.0005763 secs] 8.314: [Deallocate Metadata, 0.0000144 secs], 0.0006416 secs], 0.0014267 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Pre-cleaning process, this place clears the Region partitions that are all garbage. It can be seen from the log here that no Region has been cleared.
8.314: [GC cleanup 75M->75M(128M), 0.0016325 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
Log information and log details
(1) Parameter setting
(2)Simulation code
(3) GC logs related to code execution
(4) Summary
(1) Parameter setting
The specific parameters are as follows: Without printing the details here, let’s see when Full GC appears.
-XX:InitialHeapSize=36M -XX:MaxHeapSize=36M
-XX:G1HeapRegionSize=4M -XX:MaxGCPauseMillis=20
-XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseG1GC
-Xloggc:(2)Simulation code
public class FGCDemo12 {
private static final ArrayList list = new ArrayList();
public static void main(String[] args) throws Exception {
while(true) {
//Set an object to 256K. If it is too large, large object allocation will be performed directly and YGC cannot be simulated.
byte[] data = new byte[1024 * 1024];
for (int i = 0; i< 36; i++) {
data = new byte[1024 * 1024];
}
//Create n objects and add them to a list without recycling these arrays
for (int i = 0; i<= 36; i++) {
byte[] data2 = new byte[1024 * 1024];
// Add part of the byte array to the list
(data2);
}
(1000);
}
}
}(3) GC logs related to code execution
1. When printing details are not added, the GC information is as follows:
0.160: [GC pause (G1 Evacuation Pause) (young) 4096K->1808K(32M), 0.0028039 secs]
0.163: [GC pause (G1 Evacuation Pause) (young) 5904K->1976K(32M), 0.0017013 secs]
0.165: [GC pause (G1 Evacuation Pause) (young) 6072K->1997K(32M), 0.0012654 secs]
0.167: [GC pause (G1 Evacuation Pause) (young) 6093K->1819K(32M), 0.0012048 secs]
0.171: [GC pause (G1 Evacuation Pause) (young) 13M->2198K(32M), 0.0016891 secs]
0.174: [GC pause (G1 Evacuation Pause) (young) 14M->1900K(32M), 0.0013103 secs]
0.176: [GC pause (G1 Evacuation Pause) (young) 13M->2992K(32M), 0.0016521 secs]
0.179: [GC pause (G1 Evacuation Pause) (young) 14M->14M(32M), 0.0030006 secs]
0.183: [GC pause (G1 Evacuation Pause) (young)-- 30M->32M(32M), 0.0014989 secs]
0.184: [Full GC (Allocation Failure) 32M->23M(32M), 0.0052335 secs]
0.190: [Full GC (Allocation Failure) 23M->23M(32M), 0.0028101 secs]
0.193: [GC pause (G1 Evacuation Pause) (young) 23M->23M(32M), 0.0008639 secs]
0.194: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 23M->23M(32M), 0.0008385 secs]
0.195: [GC concurrent-root-region-scan-start]
0.195: [GC concurrent-root-region-scan-end, 0.0000051 secs]
0.195: [GC concurrent-mark-start]
//The first Full GC compressed 1M of space, from 23M to 22M; the second Full GC could not compress the space.
0.195: [Full GC (Allocation Failure) 23M->22M(32M), 0.0062830 secs]
0.201: [Full GC (Allocation Failure) 22M->22M(32M), 0.0028600 secs]
// Terminate concurrent marking
0.204: [GC concurrent-mark-abort]
0.204: [GC pause (G1 Evacuation Pause) (young) 22M->22M(32M), 0.0006367 secs]
0.205: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 22M->22M(32M), 0.0007129 secs]
0.206: [GC concurrent-root-region-scan-start]
0.206: [GC concurrent-root-region-scan-end, 0.0000050 secs]
0.206: [GC concurrent-mark-start]
//At the beginning of concurrent marking, Full GC was entered, and Full GC was performed twice. Finally, concurrent marking was terminated and an OOM exception was thrown;
//This shows that our analysis of Full GC is correct. It will be divided into two GCs. The first time will not process soft references, and the second time will process them;
0.206: [Full GC (Allocation Failure) 22M->22M(32M), 0.0024892 secs]
0.208: [Full GC (Allocation Failure) 22M->22M(32M), 0.0020168 secs]
0.210: [GC concurrent-mark-abort]2. Modify the parameters to print log details:
-XX:InitialHeapSize=36M -XX:MaxHeapSize=36M
-XX:G1HeapRegionSize=4M -XX:MaxGCPauseMillis=20
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseG1GC
-Xloggc: After adding the print log details -XX:+PrintGCDetails parameter, the log output is as follows:
CommandLine flags: -XX:G1HeapRegionSize=4194304 -XX:InitialHeapSize=37748736 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=37748736 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
//The 1st YGC
0.164: [GC pause (G1 Evacuation Pause) (young), 0.0015655 secs]
[Parallel Time: 1.1 ms, GC Workers: 8]
...
[Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->4096.0K Heap: 4096.0K(36.0M)->1896.1K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 2nd YGC
0.166: [GC pause (G1 Evacuation Pause) (young), 0.0016293 secs]
[Parallel Time: 1.1 ms, GC Workers: 8]
...
[Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 4096.0K->4096.0K Heap: 5992.1K(36.0M)->2202.0K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 3rd YGC
0.168: [GC pause (G1 Evacuation Pause) (young), 0.0014074 secs]
[Parallel Time: 0.9 ms, GC Workers: 8]
...
[Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 4096.0K->4096.0K Heap: 6298.0K(36.0M)->1777.8K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 4th YGC
0.170: [GC pause (G1 Evacuation Pause) (young), 0.0013150 secs]
[Parallel Time: 0.9 ms, GC Workers: 8]
...
[Eden: 4096.0K(4096.0K)->0.0B(8192.0K) Survivors: 4096.0K->4096.0K Heap: 5873.8K(36.0M)->1948.1K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 5th YGC
0.173: [GC pause (G1 Evacuation Pause) (young), 0.0016268 secs]
[Parallel Time: 1.2 ms, GC Workers: 8]
...
[Eden: 8192.0K(8192.0K)->0.0B(16.0M) Survivors: 4096.0K->4096.0K Heap: 10140.1K(36.0M)->2080.7K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 6th YGC
0.178: [GC pause (G1 Evacuation Pause) (young), 0.0015187 secs]
[Parallel Time: 1.1 ms, GC Workers: 8]
...
[Eden: 16.0M(16.0M)->0.0B(16.0M) Survivors: 4096.0K->4096.0K Heap: 18.0M(36.0M)->2069.6K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 7th YGC
0.181: [GC pause (G1 Evacuation Pause) (young), 0.0018350 secs]
...
[Eden: 16.0M(16.0M)->0.0B(16.0M) Survivors: 4096.0K->4096.0K Heap: 18.0M(36.0M)->6165.5K(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 8th YGC
0.183: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0032817 secs]
[Parallel Time: 2.7 ms, GC Workers: 8]
...
[Eden: 16.0M(16.0M)->0.0B(8192.0K) Survivors: 4096.0K->4096.0K Heap: 22.0M(36.0M)->24.0M(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//The 9th YGC, but here the initial mark of Mixed GC is turned on, and then it enters the concurrent mark phase.
0.187: [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0013577 secs]
[Parallel Time: 0.8 ms, GC Workers: 8]
...
[Eden: 8192.0K(8192.0K)->0.0B(8192.0K) Survivors: 4096.0K->0.0B Heap: 32.0M(36.0M)->36.0M(36.0M)]
[Times: user=0.13 sys=0.00, real=0.00 secs]
//After entering the concurrent marking phase of Mixed GC, when starting concurrent marking, it directly enters the Full GC state
0.189: [GC concurrent-root-region-scan-start]
0.189: [GC concurrent-root-region-scan-end, 0.0000047 secs]
0.189: [GC concurrent-mark-start]
//You can see that when Full GC was performed for the first time, some garbage was recovered and the heap memory was organized;
//After Full GC, there are no specific details of the Eden area and Survivor area;
//Because after the Full GC ends, all partitions will be marked as Old, and then some Regions will be reselected to become Eden regions;
0.189: [Full GC (Allocation Failure) 36M->23M(36M), 0.0051574 secs]
[Eden: 0.0B(8192.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 36.0M(36.0M)->23.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then concurrent marking will be terminated directly at this time and will no longer be carried out;
0.194: [GC concurrent-mark-abort]
//After the program runs for a period of time, the Eden area is filled again, and then continues to enter YGC.
0.194: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0007054 secs]
[Parallel Time: 0.2 ms, GC Workers: 8]
...
//Note: After Full GC, the Eden area is still a Region, and after this YGC, no garbage has been recycled;
[Eden: 4096.0K(4096.0K)->0.0B(8192.0K) Survivors: 0.0B->0.0B Heap: 27.7M(36.0M)->27.7M(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then the program continues to run, and the first Full GC can only be triggered here, and only 1M of space is compressed and organized.
0.195: [Full GC (Allocation Failure) 27M->26M(36M), 0.0026733 secs]
[Eden: 0.0B(8192.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 27.7M(36.0M)->26.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then trigger the second Full GC. This time the soft reference will be processed;
//Our program does not have soft references, so Full GC cannot free up enough space this time;
0.198: [Full GC (Allocation Failure) 26M->26M(36M), 0.0020266 secs]
[Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->26.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then enter YGC again, because the Eden area is 0, and the allocation attempt fails again.
0.200: [GC pause (G1 Evacuation Pause) (young), 0.0007709 secs]
[Parallel Time: 0.3 ms, GC Workers: 8]
...
[Eden: 0.0B(4096.0K)->0.0B(8192.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->26.7M(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Then enter YGC again and turn on the initial mark of Mixed GC
0.201: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0006809 secs]
[Parallel Time: 0.3 ms, GC Workers: 8]
...
[Eden: 0.0B(8192.0K)->0.0B(8192.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->26.7M(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.202: [GC concurrent-root-region-scan-start]
0.202: [GC concurrent-root-region-scan-end, 0.0000054 secs]
0.202: [GC concurrent-mark-start]
0.202: [Full GC (Allocation Failure) 26M->25M(36M), 0.0067177 secs]
[Eden: 0.0B(8192.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
//Trigger Full GC
0.209: [Full GC (Allocation Failure) 25M->25M(36M), 0.0022560 secs]
[Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
// Terminate the concurrent mark of Mixed GC
0.211: [GC concurrent-mark-abort]
//Trigger YGC
0.211: [GC pause (G1 Evacuation Pause) (young), 0.0006518 secs]
[Parallel Time: 0.3 ms, GC Workers: 8]
...
[Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
////Then enter YGC again and turn on the initial mark of Mixed GC
0.212: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0006747 secs]
[Parallel Time: 0.3 ms, GC Workers: 8]
...
[Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.213: [GC concurrent-root-region-scan-start]
0.213: [GC concurrent-root-region-scan-end, 0.0000046 secs]
0.213: [GC concurrent-mark-start]
//Trigger the first Full GC
0.213: [Full GC (Allocation Failure) 25M->25M(36M), 0.0025106 secs]
[Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
//Trigger the second Full GC
0.216: [Full GC (Allocation Failure) 25M->25M(36M), 0.0020506 secs]
[Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K (1056768K)]
[Times: user=0.00 sys=0.00, real=0.00 secs]
// Terminate the concurrent mark of Mixed GC
0.218: [GC concurrent-mark-abort]Finally, after many attempts, it could not be allocated and could only OOM. It can be seen that G1 is actually more cautious about OOM. After many YGC concurrent markings and multiple FGC processes, an OOM exception was finally thrown. So it is not that OOM will be entered after two FGC failures.
Note: After FGC is completed, all partitions will be marked as Old, and then some Regions will be reselected to become Eden regions.
(4) Summary
FGC is more difficult when using G1 than when using ParNew + CMS, and the number of attempts is also very high in the log. The entire process of FGC is relatively simple and crude. If the space cannot be compressed, OOM will occur.