Series columns: SERIES of JVM columns

Series of articles:

JVM performance Tuning (1) — JVM memory model and class loading operation mechanism
JVM performance Tuning (2) — garbage collection algorithms and garbage collectors

Memory Settings

Setting up JVM memory

1. JVM memory allocation takes the following parameters

-Xms: indicates the heap memory size
-Xmx: indicates the maximum size of heap memory
-xmn: Cenozoic size, minus the Cenozoic size is the old age size
-Xss: indicates the size of the thread stack
-xx :NewSize: indicates the size of the initial new generation
-xx :MaxNewSize: indicates the maximum size of the new generation
-xx :InitialHeapSize: indicates the InitialHeapSize
-xx :MaxHeapSize: indicates the maximum heap size
-xx :MetaspaceSize :MetaspaceSize :MetaspaceSize :MetaspaceSize :MetaspaceSize :MetaspaceSize :MetaspaceSize
-xx :MaxMetaspaceSize: specifies the maximum size of the metasize (permanent generation). Before JDK8, use -xx :MaxPermSize
-xx :SurvivorRatio: ratio of Eden zones and Survivor zones in the new generation. The default value is 8, that is, 8:1:1

Generally, -xms and -xmx are set to the same size, and -xx :MetaspaceSize and -xx :MaxMetaspaceSize are set to the same size. -xms is equivalent to -xx :InitialHeapSize, -xmx is equivalent to -xx :MaxHeapSize; -xmn is equivalent to -xx :MaxNewSize.

2. In IDEA, you can set JVM parameters as follows

3. You can set the command line in the following format

java -jar -Xms1G -Xmx1G -Xmn512M -Xss1M -XX:MetaspaceSize=128M -XX:MaxMetaspaceSize=128M app.jar
Copy the code

Outputting GC Logs

Setting GC Parameters

You can view GC logs by adding the following parameters at startup:

-XX:+PrintGC: Prints GC logs
-XX:+PrintGCDetails: Prints detailed GC logs
-XX:+PrintGCTimeStamps: Prints the time of each GC occurrence
-Xloggc:./gc.log: Sets the path to the GC log file

For example, I added the following JVM startup parameters to IDEA:

-Xms1G
-Xmx1G
-Xmn512M
-Xss1M
-XX:MetaspaceSize=128M
-XX:MaxMetaspaceSize=128M
-XX:SurvivorRatio=8
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:./gc.log
Copy the code

After starting the program, the following logs are printed:

 1 Java HotSpot(TM) 64-Bit Server VM (25.191-b12) for windows-amd64 JRE (1.8. 0 _191-b12), built on Oct  6 2018 09:29:03 by "java_re" with MS VC++ 10.0 (VS2010)
 2 Memory: 4k page, physical 33408872k(22219844k free), swap 35506024k(21336808k free)
 3 CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:CompressedClassSpaceSize=125829120 -XX:InitialHeapSize=1073741824 -XX:+ManagementServer -XX:MaxHeapSize=1073741824 -XX:MaxMetaspaceSize=134217728 -XX:MaxNewSize=536870912 -XX:MetaspaceSize=134217728 -XX:NewSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:ThreadStackSize=1024 -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
 4 2020-09-25T13:00:41.631+ 0800:4.013: [GC (Allocation Failure) [PSYoungGen: 419840K->20541K(472064K)] 419840K->20573K(996352K), 0.0118345 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 5 2020-09-25T13:00:44.252+ 0800:6.633: [GC (Allocation Failure) [PSYoungGen: 440381K->39872K(472064K)] 440413K->39928K(996352K), 0.0180292 secs] [Times: user=0.08 sys=0.08, real=0.02 secs] 
 6.7 2020-09-25T13:06:58.361+ 0800:380.743: [GC (Allocation Failure) [PSYoungGen: 422656K->14159K(472064K)] 610503K->204082K(996352K), 0.0111278 secs] [Times: user=0.16 sys=0.00, real=0.01 secs] 
 8 Heap
 9  PSYoungGen      total 472064K, used 406352K [0x00000000e0000000.0x0000000100000000.0x0000000100000000)
10   eden space 419840K, 93% used [0x00000000e0000000.0x00000000f7f00528.0x00000000f9a00000)
11   from space 52224K, 27% used [0x00000000f9a00000.0x00000000fa7d3d70.0x00000000fcd00000)
12   to   space 52224K, 0% used [0x00000000fcd00000.0x00000000fcd00000.0x0000000100000000)
13  ParOldGen       total 524288K, used 189923K [0x00000000c0000000.0x00000000e0000000.0x00000000e0000000)
14   object space 524288K, 36% used [0x00000000c0000000.0x00000000cb978d08.0x00000000e0000000)
15  Metaspace       used 111852K, capacity 117676K, committed 117888K, reserved 1153024K
16   class space    used 13876K.capacity 14914K.committed 14976K.reserved 1048576K
Copy the code

From the third line CommandLine Flags you get the following information:

-xx :InitialHeapSize=1073741824 :InitialHeapSize is 1G (equal to the value set by -xms)
-xx :MaxHeapSize=1073741824: Maximum heap memory 1G (equal to the value set by -xmx)
-xx :NewSize=536870912 :New generation initial size 512M (equal to the value set by -xmn)
-xx :MaxNewSize=536870912: New generation initial size 512M (equal to the value set by -xmn)
-xx :MetaspaceSize=134217728: The MetaspaceSize size is 128 MB
-xx :MaxMetaspaceSize=134217728: The maximum metasize space is 128 MB
-xx :SurvivorRatio=8: ratio of Eden and Survivor in the new generation
-xx :ThreadStackSize=1024: The size of the thread stack is 1M
-xx :+UseParallelGC: use the younger Generation of the Parallel Avenge + the older generation of the Parallel avenge avenge.

View default parameters

If you want to see the JVM’s default parameters, you can see the JVM’s default parameters in the GC log by adding the parameters to the JVM to print the GC log.

You can also add the -xx :+PrintFlagsFinal parameter to the startup parameter, which will print all the system parameters. You can see your own parameters or the system default parameters.

The GC log

The subsequent logs are generated for each garbage collection, and each line of the log describes the GC execution, such as the fourth line of the GC log:

2020-09-25T13:00:41.631+ 0800:4.013: [GC (Allocation Failure)] [Times: user=0.00 sys=0.00, real= 0.01secs]Copy the code

The details are as follows:

The T13:2020-09-25 00:41. 631 + 0800: Point in time when GC occurs.
4.013: How long GC occurred after the system was running, in seconds, here is a GC occurred after the system was running 4.013 seconds.
GC (Allocation Failure): indicates what triggers GC, which in this case is GC due to an object allocation failure.
PSYoungGenThe Parallel Avenge avenge is used to trigger the younger generation of the garbage collector.
419840K->20541K: a GC was performed on the young generation, which used 419840K before GC, and 20541K objects survived after GC.
(472064K): The available space of the young generation is 472064K, that is 461M, why 461M? Since the size of the new generation is 512M, Eden area occupies 409.6m, and the two Survivor areas each occupy 51.2m, the available space of the young generation is the size of Eden+ one Survivor, namely 460.8m, or about 461M.
419840K->20573K: Total heap memory used 419840K before GC and 20573K after GC.
(996352K)The size of the entire heap is 996352K, or 973M, which is 461M for the younger generation plus 512 M for the older generation
0.0118345 secs: Time spent by this GC
Times: user=0.00 sys=0.00, real=0.01 SECs: total GC time

GC when the JVM exits

After the program finishes running, it prints some logs, after line 12, which shows the current heap memory usage:

1 Heap
2  PSYoungGen      total 472064K, used 406352K [0x00000000e0000000.0x0000000100000000.0x0000000100000000)
3   eden space 419840K, 93% used [0x00000000e0000000.0x00000000f7f00528.0x00000000f9a00000)
4   from space 52224K, 27% used [0x00000000f9a00000.0x00000000fa7d3d70.0x00000000fcd00000)
5   to   space 52224K, 0% used [0x00000000fcd00000.0x00000000fcd00000.0x0000000100000000)
6  ParOldGen       total 524288K, used 189923K [0x00000000c0000000.0x00000000e0000000.0x00000000e0000000)
7   object space 524288K, 36% used [0x00000000c0000000.0x00000000cb978d08.0x00000000e0000000)
8  Metaspace       used 111852K, capacity 117676K, committed 117888K, reserved 1153024K
9   class space    used 13876K.capacity 14914K.committed 14976K.reserved 1048576K
Copy the code

The details are as follows:

PSYoungGen total 472064K, used 406352KThe Parallel Exploiter is responsible for a younger generation of 4,72064K of memory, currently using 406352K.
eden space 419840K, 93% used: The space in Eden area is 419840K (410M), 93% of which has been used.
from space 52224K, 27% used: The space From the Survivor zone is 52224K (51M), 27% used.
to space 52224K, 0% used: The space in the To Survivor zone is 52224K (51M), and 0% is used, so it is completely free.
ParOldGen total 524288K, used 189923K: Parallel Old collector is responsible for a total of 524288K (512M), currently used 189923K (185.4m).
object space 524288K, 36% used: The total size of the old chronospace is 524288K (512M), 36% of which is used.
Metaspace & class space: Metaspace metadata space and Class space, total capacity, memory used, etc.

Memory allocation and reclamation policies

Let’s take a look at some demos with GC logs to see when GC is triggered and how objects are distributed in the heap.

The object is first allocated to the Eden region

We verify that the following object is allocated to Eden by using the following program:

public class GCMain {
    static final int _1M = 1024 * 1024;

    public static void main(String[] args) {
        byte[] b1 = new byte[_1M * 30];
        byte[] b2 = new byte[_1M * 30]; }}Copy the code

JVM parameters are set as follows: 200M heap, 100M young generation, 80M Eden region, 10M Survivor, 100M old generation. Use the default Parallel Exploiter + Parallel Old collector.

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:+UseParallelGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

After the program finishes running, view the running GC log:

 1 Java HotSpot(TM) 64-Bit Server VM (25.191-b12) for windows-amd64 JRE (1.8. 0 _191-b12), built on Oct  6 2018 09:29:03 by "java_re" with MS VC++ 10.0 (VS2010)
 2 Memory: 4k page, physical 33408872k(23013048k free), swap 35506024k(22095152k free)
 3 CommandLine flags: -XX:InitialHeapSize=209715200 -XX:MaxHeapSize=209715200 -XX:MaxNewSize=104857600 -XX:NewSize=104857600 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
 4 Heap
 5  PSYoungGen      total 92160K, used 68062K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
 6   eden space 81920K, 83% used [0x00000000f9c00000.0x00000000fde77ba0.0x00000000fec00000)
 7   from space 10240K, 0% used [0x00000000ff600000.0x00000000ff600000.0x0000000100000000)
 8   to   space 10240K, 0% used [0x00000000fec00000.0x00000000fec00000.0x00000000ff600000)
 9  ParOldGen       total 102400K, used 0K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
10   object space 102400K, 0% used [0x00000000f3800000.0x00000000f3800000.0x00000000f9c00000)
11  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
12   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

As you can see from line 5, the total available space for the young generation is 92160K (90M), and 68062K (66.4m) has been used. The code creates two 30M byte arrays. Why does it take up 66.4m bytes? The extra objects can be thought of as the extra memory needed by the object array itself and some extra objects created by the program at run time, called unknown objects.
After line 6, you can see that Eden is using 83%, and From Survivor, To Survivor, and old age are using 0%. You can confirm that the object is first allocated to the Eden region.

Eden block full trigger YoungGC

Use the following JVM parameters:

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:+UseParallelGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Run the following code, lines 2, 3, and 4 will generate 60MB of garbage objects, and when line 6 is reallocated, the Eden space will run out, triggering a YoungGC.

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 30];
    b1 = new byte[_1M * 30];
    b1 = null;

    byte[] b2 = new byte[_1M * 30];
}
Copy the code

If you look at the GC log, you can see that a Young GC was triggered:

 1 2020-09-26T00:14:16.832+ 0800:0.194: [GC (Allocation Failure) [PSYoungGen: 66424K->815K(92160K)] 66424K->823K(194560K), 0.0010813 secs] [Times: user=0.08 sys=0.08, real=0.00 secs] 
 2 Heap
 3  PSYoungGen      total 92160K, used 33993K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
 4   eden space 81920K, 40% used [0x00000000f9c00000.0x00000000fbc66800.0x00000000fec00000)
 5   from space 10240K, 7% used [0x00000000fec00000.0x00000000feccbca0.0x00000000ff600000)
 6   to   space 10240K, 0% used [0x00000000ff600000.0x00000000ff600000.0x0000000100000000)
 7  ParOldGen       total 102400K, used 8K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 8   object space 102400K, 0% used [0x00000000f3800000.0x00000000f3802000.0x00000000f9c00000)
 9  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
10   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K 1 Java HotSpot(TM) 64 -Bit Server VM(25.191 -b12) for windows-amd64 JRE(1.8.0 comes with_191-b12), built on Oct6, 2018 09:29:03by "java_re" with MS VC+ + 10.0 (VS20102)Memory4:k page.physical 33408872k(22977952k free), swap 35506024k(21515696k free)
 3 CommandLine flags: -XX:InitialHeapSize=209715200 -XX:MaxHeapSize=209715200 -XX:MaxNewSize=104857600 -XX:NewSize=104857600 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=41943040 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
 4 Heap
 5  par new generation   total 92160K, used 6622K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 6   eden space 81920K,   8% used [0x00000000f3800000.0x00000000f3e77b80.0x00000000f8800000)
 7   from space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
 8   to   space 10240K,   0% used [0x00000000f9200000.0x00000000f9200000.0x00000000f9c00000)
 9  concurrent mark-sweep generation total 102400K, used 40960K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
10  Metaspace       used 3046K, capacity 4556K, committed 4864K, reserved 1056768K
11   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

In line 1, we can see that a YoungGC is triggered due to a memory allocation failure. The whole heap occupied 66424K before recycling and survived 823K after recycling.
Line 3 shows that after the program ends, the new generation uses 33993K, including the last B2 object.
As you can see in line 5, after the Young GC, the surviving 815K objects enter the FROM Survivor zone and occupy 7% of the space.

From the above analysis, you can confirm that when the Eden region is nearly full and cannot allocate memory for newborn objects, a Young GC is triggered and the surviving objects are copied to a survivor region.

Large objects will go straight to the old age

To control large object threshold can be – XX: PretenureSizeThreshold parameter Settings, but it is only right Serial and ParNew collector, the Parallel Scavenge is not effective, So here we use the collector combination of ParNew + CMS and set the large object threshold to 4M:

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=40M -XX:+UseConcMarkSweepGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Create a 40M object directly by running the following code:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 40];
}
Copy the code

To view GC logs:

 1 Java HotSpot(TM) 64-Bit Server VM (25.191-b12) for windows-amd64 JRE (1.8. 0 _191-b12), built on Oct  6 2018 09:29:03 by "java_re" with MS VC++ 10.0 (VS2010)
 2 Memory: 4k page, physical 33408872k(22977952k free), swap 35506024k(21515696k free)
 3 CommandLine flags: -XX:InitialHeapSize=209715200 -XX:MaxHeapSize=209715200 -XX:MaxNewSize=104857600 -XX:NewSize=104857600 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=41943040 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
 4 Heap
 5  par new generation   total 92160K, used 6622K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 6   eden space 81920K,   8% used [0x00000000f3800000.0x00000000f3e77b80.0x00000000f8800000)
 7   from space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
 8   to   space 10240K,   0% used [0x00000000f9200000.0x00000000f9200000.0x00000000f9c00000)
 9  concurrent mark-sweep generation total 102400K, used 40960K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
10  Metaspace       used 3046K, capacity 4556K, committed 4864K, reserved 1056768K
11   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

As you can see in lines 3, 5, and 9, the -xx :+UseConcMarkSweepGC parameter is enabled by default for ParNew + CMS’s collector.
As can be seen from lines 5 and 6, there will still be unknown objects about 6M in Eden area.
As you can see in line 9, CMS is responsible for 102400K (100M) of memory in the old age, using 40960K (40M), which is the B1 object created in the code.

So you can confirm, over – XX: PretenureSizeThreshold parameters set of large objects will be directly into old age.

Long-lived objects will enter the old age

The object is born in Eden. When Eden is full, YoungGC will be triggered to copy the surviving objects in Eden to survivor. At this time, the GC age of the objects is set to 1 year old. Each time an object passes through GC, its GC age increases by one year, and when it passes a certain threshold it is promoted to the old age. The threshold for GC age can be set with the parameter -xx :MaxTenuringThreshold, which defaults to 15.

Set the following JVM parameters: Eden region 80M, survivor ratio 10M, GC age threshold 2.

-Xms200M -Xmx200M -Xmn100M -XX:MaxTenuringThreshold=2 -XX:PretenureSizeThreshold=40M -XX:+UseConcMarkSweepGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Line 4, 5, and 6 will generate 70M garbage objects in Eden. When line 8 creates a 35M garbage object, Eden will run out of space and trigger the first YoungGC:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 2]; // b1 indicates that the number of long-term survivable objects accounts for 2M

    byte[] b2 = new byte[_1M * 35];
    b2 = new byte[_1M * 35];
    b2 = null;

    byte[] b3 = new byte[_1M * 35];
    //b3 = new byte[_1M * 35];
    //b3 = null;
    //
    //byte[] b4 = new byte[_1M * 35];
    //b4 = new byte[_1M * 35];
    //b4 = null;
    //
    //byte[] bx = new byte[_1M * 2];
    //byte[] b5 = new byte[_1M * 35];
}
Copy the code

To view GC logs:

1 2020-09-25T23:47:20.648+ 0800:0.198: [GC (Allocation Failure) 2020-09-25T23:47:20.648+ 0800:0.198: [ParNew: 78712K->2769K(92160K), 0.0013440 secs] 78712K->2769K(194560K), 0.0014923 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2 Heap
3  par new generation   total 92160K, used 41067K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
4   eden space 81920K,  46% used [0x00000000f3800000.0x00000000f5d66800.0x00000000f8800000)
5   from space 10240K,  27% used [0x00000000f9200000.0x00000000f94b4600.0x00000000f9c00000)
6   to   space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
7  concurrent mark-sweep generation total 102400K, used 0K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
8  Metaspace       used 3047K, capacity 4556K, committed 4864K, reserved 1056768K
9   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

As can be seen, 2769K objects survived after the first YoungGC, and then copied to the from survivor region, accounting for 27% of the space size, including 2M B1 objects +700K unknown objects. The GC age of b1 object is 1.

Run the following code again, again at line 12, to trigger a second YoungGC:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 2]; // b1 indicates that the number of long-term survivable objects accounts for 2M

    byte[] b2 = new byte[_1M * 35];
    b2 = new byte[_1M * 35];
    b2 = null;

    byte[] b3 = new byte[_1M * 35];
    b3 = new byte[_1M * 35];
    b3 = null;

    byte[] b4 = new byte[_1M * 35];
    //b4 = new byte[_1M * 35];
    //b4 = null;
    //
    //byte[] bx = new byte[_1M * 2];
    //byte[] b5 = new byte[_1M * 35];
}
Copy the code

To view GC logs:

 1 2020-09-25T23:53:57.325+ 0800:0.196: [GC (Allocation Failure) 2020-09-25T23:53:57.325+ 0800:0.196: [ParNew: 78712K->2770K(92160K), 0.0014935 secs] 78712K->2770K(194560K), 0.0016180 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 2 2020-09-25T23:53:57.331+ 0800:0.201: [GC (Allocation Failure) 2020-09-25T23:53:57.331+ 0800:0.201: [ParNew: 77693K->2888K(92160K), 0.0013393 secs] 77693K->2888K(194560K), 0.0013890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 3 Heap
 4  par new generation   total 92160K, used 40367K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 5   eden space 81920K,  45% used [0x00000000f3800000.0x00000000f5c99b30.0x00000000f8800000)
 6   from space 10240K,  28% used [0x00000000f8800000.0x00000000f8ad2130.0x00000000f9200000)
 7   to   space 10240K,   0% used [0x00000000f9200000.0x00000000f9200000.0x00000000f9c00000)
 8  concurrent mark-sweep generation total 102400K, used 0K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
 9  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
10   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

It can be seen that 2888K objects still survive after the second YoungGC, which is copied to another survivor area, accounting for 28% of the memory, including 2M B1 objects +700K unknown objects. The GC age of b2 object is increased by 1 to 2.

Run the following code again, line 17 triggers the third YoungGC:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 2]; // b1 indicates that the number of long-term survivable objects accounts for 2M

    byte[] b2 = new byte[_1M * 35];
    b2 = new byte[_1M * 35];
    b2 = null;

    byte[] b3 = new byte[_1M * 35];
    b3 = new byte[_1M * 35];
    b3 = null;

    byte[] b4 = new byte[_1M * 35];
    b4 = new byte[_1M * 35];
    b4 = null;

    byte[] bx = new byte[_1M * 2];
    byte[] b5 = new byte[_1M * 35];
}
Copy the code

To view GC logs:

 1 2020-09-26T00:00:39.242+ 0800:0.188: [GC (Allocation Failure) 2020-09-26T00:00:39.243+ 0800:0.188: [ParNew: 78712K->2749K(92160K), 0.0012472 secs] 78712K->2749K(194560K), 0.0013625 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 2 2020-09-26T00:00:39.247+ 0800:0.193: [GC (Allocation Failure) 2020-09-26T00:00:39.247+ 0800:0.193: [ParNew: 77672K->2867K(92160K), 0.0013000 secs] 77672K->2867K(194560K), 0.0013396 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 3 2020-09-26T00:00:39.252+ 0800:0.197: [GC (Allocation Failure) 2020-09-26T00:00:39.252+ 0800:0.197: [ParNew: 78732K->2048K(92160K), 0.0031018 secs] 78732K->4716K(194560K), 0.0031488 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
 4 Heap
 5  par new generation   total 92160K, used 38707K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 6   eden space 81920K,  44% used [0x00000000f3800000.0x00000000f5bcce50.0x00000000f8800000)
 7   from space 10240K,  20% used [0x00000000f9200000.0x00000000f9400010.0x00000000f9c00000)
 8   to   space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
 9  concurrent mark-sweep generation total 102400K, used 2668K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
10  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
11   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

After the third YoungGC, the young generation survives 2048K (2M), which is bx. Bx is copied to from survivor, and the from survivor takes up exactly 20% (2M). At this time, 2668K was used in the old age, that is, 2M B1 object +600K unknown object.

Therefore, it can be determined that the GC age of survivor objects in survivor zone has exceeded the set threshold when the third YoungGC attempt is made to replicate the survivor objects in Eden +from survivor zone, and the objects exceeding the threshold will be copied to the old age.

Dynamic object age determination

Age determination of dynamic objects means that, before replication, if age 1+ age 2+ age 3+… + When the total of objects of age n is greater than 50% of the survivor zone, surviving objects of age n and older enter the old age, not necessarily 15 years old.

Set the following JVM parameters:

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=40M -XX:+UseConcMarkSweepGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Run the following code:

public static void main(String[] args) {
    byte[] x1 = new byte[_1M * 3];

    byte[] b1 = new byte[_1M * 30];
    b1 = new byte[_1M * 30];
    b1 = null;

    byte[] b2 = new byte[_1M * 30]; // Trigger a GC

    byte[] x2 = new byte[_1M * 2];

    b2 = new byte[_1M * 30];
    b2 = null;

    byte[] b3 = new byte[_1M * 30]; // Trigger a GC

    //byte[] x3 = new byte[_1M];
    //
    //b3 = new byte[_1M * 30];
    //b3 = null;
    //
    //byte[] b4 = new byte[_1M * 30]; // Trigger a GC
}
Copy the code

To view GC logs:

 1 2020-09-26T00:50:51.099+ 0800:0.211: [GC (Allocation Failure) 2020-09-26T00:50:51.099+ 0800:0.211: [ParNew: 69496K->3787K(92160K), 0.0020708 secs] 69496K->3787K(194560K), 0.0021864 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 2 2020-09-26T00:50:51.104+ 0800:0.217: [GC (Allocation Failure) 2020-09-26T00:50:51.104+ 0800:0.217: [ParNew: 70513K->6007K(92160K), 0.0030657 secs] 70513K->6007K(194560K), 0.0031105 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 3 Heap
 4  par new generation   total 92160K, used 38366K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 5   eden space 81920K,  39% used [0x00000000f3800000.0x00000000f5799b30.0x00000000f8800000)
 6   from space 10240K,  58% used [0x00000000f8800000.0x00000000f8dddf18.0x00000000f9200000)
 7   to   space 10240K,   0% used [0x00000000f9200000.0x00000000f9200000.0x00000000f9c00000)
 8  concurrent mark-sweep generation total 102400K, used 0K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
 9  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
10   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

Combining the code with the GC log shows that after line 15, the code triggers two GC’s, with x1’s GC age of 2 and X2’s GC age of 1. From survivor accounts for 58%, which also shows that the dynamic age rule is determined before replication.

Run the following code again:

public static void main(String[] args) {
    byte[] x1 = new byte[_1M * 3];

    byte[] b1 = new byte[_1M * 30];
    b1 = new byte[_1M * 30];
    b1 = null;

    byte[] b2 = new byte[_1M * 30]; // Trigger a GC

    byte[] x2 = new byte[_1M * 2];

    b2 = new byte[_1M * 30];
    b2 = null;

    byte[] b3 = new byte[_1M * 30]; // Trigger a GC

    byte[] x3 = new byte[_1M];

    b3 = new byte[_1M * 30];
    b3 = null;

    byte[] b4 = new byte[_1M * 30]; // Trigger a GC
}
Copy the code

To view GC logs:

 1 2020-09-26T00:57:03.279+ 0800:0.197: [GC (Allocation Failure) 2020-09-26T00:57:03.279+ 0800:0.197: [ParNew: 69496K->3785K(92160K), 0.0020626 secs] 69496K->3785K(194560K), 0.0021906 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 2 2020-09-26T00:57:03.285+ 0800:0.203: [GC (Allocation Failure) 2020-09-26T00:57:03.285+ 0800:0.203: [ParNew: 70511K->5980K(92160K), 0.0028174 secs] 70511K->5980K(194560K), 0.0028673 secs] [Times: user=0.16 sys=0.00, real=0.00 secs] 
 3 2020-09-26T00:57:03.290+ 0800:0.208: [GC (Allocation Failure) 2020-09-26T00:57:03.290+ 0800:0.208: [ParNew: 70832K->3072K(92160K), 0.0031929 secs] 70832K->6764K(194560K), 0.0032401 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 4 Heap
 5  par new generation   total 92160K, used 34611K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 6   eden space 81920K,  38% used [0x00000000f3800000.0x00000000f56cce50.0x00000000f8800000)
 7   from space 10240K,  30% used [0x00000000f9200000.0x00000000f9500020.0x00000000f9c00000)
 8   to   space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
 9  concurrent mark-sweep generation total 102400K, used 3692K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
10  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
11   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

Combining the code with the GC log, it can be seen that when the code runs to line 22, the third GC is triggered. By the third GC replication, the x2 object of age 1 (2M) + the X1 object of age 2 (3M) + the unknown object of age 2 in survivor has exceeded 50% of survivor. At this point, dynamic age determination rules are triggered to promote the object whose age is above 2 to the old age.
As you can see from line 7, 30% (3M) of the objects in the survivor zone are x2 (2M) + x3 (1M) that survived the collection.
From line 9, we can see that the old age uses 3692K (3.6m), indicating that x1 (3M) + unknown object (around 500K) is promoted to the old age by dynamic age judgment.

Run the following code again: line 19 makes it garbage before the third GC.

public static void main(String[] args) {
    byte[] x1 = new byte[_1M * 3];

    byte[] b1 = new byte[_1M * 30];
    b1 = new byte[_1M * 30];
    b1 = null;

    byte[] b2 = new byte[_1M * 30]; // Trigger a GC

    byte[] x2 = new byte[_1M * 2];

    b2 = new byte[_1M * 30];
    b2 = null;

    byte[] b3 = new byte[_1M * 30]; // Trigger a GC

    byte[] x3 = new byte[_1M];

    x1 = null; // x1 becomes garbage
    b3 = new byte[_1M * 30];
    b3 = null;

    byte[] b4 = new byte[_1M * 30]; // Trigger a GC
}
Copy the code

To view GC logs:

 1 2020-09-29T12:48:49.695+ 0800:0.179: [GC (Allocation Failure) 2020-09-29T12:48:49.695+ 0800:0.179: [ParNew: 69496K->3781K(92160K), 0.0018195 secs] 69496K->3781K(194560K), 0.0019372 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 2 2020-09-29T12:48:49.701+ 0800:0.184: [GC (Allocation Failure) 2020-09-29T12:48:49.701+ 0800:0.184: [ParNew: 70508K->5955K(92160K), 0.0027981 secs] 70508K->5955K(194560K), 0.0028417 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 3 2020-09-29T12:48:49.706+ 0800:0.189: [GC (Allocation Failure) 2020-09-29T12:48:49.706+ 0800:0.189: [ParNew: 70807K->3072K(92160K), 0.0032486 secs] 70807K->3692K(194560K), 0.0032909 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
 4 Heap
 5  par new generation   total 92160K, used 34611K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
 6   eden space 81920K,  38% used [0x00000000f3800000.0x00000000f56cce50.0x00000000f8800000)
 7   from space 10240K,  30% used [0x00000000f9200000.0x00000000f9500020.0x00000000f9c00000)
 8   to   space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
 9  concurrent mark-sweep generation total 102400K, used 620K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
10  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
11   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

From the log analysis, although the x1 object of age 2 becomes garbage object, but after the third GC, there are still 620K more objects in the old age. Note In the third YoungGC session, the FromSurvivor age 1 + age 2 + will be determined by the dynamic age before the surviving objects in Eden and FromSurvivor zones are copied to ToSurvivor zones. Objects of age N, and it judges all objects, not just those marked as alive. However, when objects older than n are copied to the old age, only objects marked as alive are copied.

Unable to enter Survivor zone directly into the old age

If the Eden + from survivor zone is not placed in the to Survivor zone, part of the objects will be placed in the old age.

Use the following JVM parameters:

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=40M -XX:+UseConcMarkSweepGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Run the following code:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 3];
    byte[] b2 = new byte[_1M * 8];

    byte[] b3 = new byte[_1M * 30];
    b3 = new byte[_1M * 30];
    b3 = null;

    byte[] b4 = new byte[_1M * 30]; / / triggers the GC
}
Copy the code

To view GC logs:

1 2020-09-26T01:20:03.727+ 0800:0.186: [GC (Allocation Failure) 2020-09-26T01:20:03.727+ 0800:0.186: [ParNew: 77688K->3799K(92160K), 0.0059624 secs] 77688K->11993K(194560K), 0.0060861 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2 Heap
3  par new generation   total 92160K, used 36977K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
4   eden space 81920K,  40% used [0x00000000f3800000.0x00000000f5866800.0x00000000f8800000)
5   from space 10240K,  37% used [0x00000000f9200000.0x00000000f95b5e00.0x00000000f9c00000)
6   to   space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
7  concurrent mark-sweep generation total 102400K, used 8194K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
8  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
9   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

Combining the code with the GC log shows that after YoungGC, the surviving objects cannot be copied into a survivor zone, so some of the objects are simply promoted to older ages. 37% (3.7M) from survivor zone can be considered as B1 object (3M) + 700K unknown object. Older generations used 8194K (8M), which is b2 object (8M).

Note that instead of promoting all surviving objects to the old age, some objects are promoted to the old age and some are copied into survivor zones.

Guarantee principle of old chronospatial allocation

If a large number of objects survive in the YougGC generation, but the survivor zone is no longer available, then you have to move to the old age, but then you find that the old age is no longer able to accommodate these objects, what happens? In fact, the JVM has an old age space allocation guarantee mechanism to ensure that objects can be old age.

Before executing each YoungGC, the JVM checks whether the maximum contiguous available space in the old generation is greater than the total size of all objects in the new generation. Because in extreme cases, after the YoungGC generation, all the objects will survive, but the survivor zone will not fit, and then all the objects will enter the old age. If the available contiguous space of the old generation is greater than the total size of all objects of the new generation, then you can safely YoungGC. But if the memory size is less than the old s new generation total size of the object, it is not enough space in the new generation of all possible old s live objects, this time the JVM will check – XX: HandlePromotionFailure parameters are allowed to guarantee failure, if allowed, It will determine whether the maximum available continuous space of the old age is greater than the average size of the objects promoted to the old age. If so, a YoungGC will be attempted, as soon as this YoungGC is risky. If less than, or – XX: HandlePromotionFailure parameters are not allowed to guarantee fail, then will conduct a Full GC.

After allowing the guarantee to fail and attempting YoungGC, three scenarios can occur:

After YoungGC, the size of the surviving object is smaller than that of survivor, and the surviving object enters the survivor zone
After YoungGC, the size of the surviving object is larger than survivor but smaller than the size of the large available space of the old age. In this case, the old age is directly entered.
YoungGC occurs when the surviving object is larger than survivor and larger than the large available space of the old age"Handle Promotion Failure"The Full GC is triggered. If there is not enough space in the old years after Full GC, OOM memory will run out.

To understand the guarantee principle of space allocation, see the following figure:

Distribution of collateral rules after JDK7 some change, no longer judge – XX: HandlePromotionFailure parameters. When YoungGC occurs, you can YoungGC as long as the contiguous space of the old age is larger than the total size of the new generation object, or larger than the average size of the previous promotions, otherwise you can FullGC.

The JVM parameters are set as follows: 100M old age, 80M Eden zone, 10M survivor zone, and 35M large object threshold.

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=35M -XX:+UseConcMarkSweepGC 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Run the following code:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M * 35];
    byte[] b2 = new byte[_1M * 35];

    byte[] b3 = new byte[_1M * 30];
    b3 = new byte[_1M * 30];
    b3 = null;

    byte[] b4 = new byte[_1M * 30]; / / triggers the GC
}
Copy the code

To view GC logs:

 1 2020-09-26T02:53:17.908+ 0800:0.210: [GC (Allocation Failure) 2020-09-26T02:53:17.909+ 0800:0.210: [ParNew: 66424K->707K(92160K), 0.0008820 secs] 138104K->72387K(194560K), 0.0010026 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 2 2020-09-26T02:53:17.911+ 0800:0.213: [GC (CMS Initial Mark) [1 CMS-initial-mark: 71680K(102400K)] 103107K(194560K), 0.0002821 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 3 2020-09-26T02:53:17.912+ 0800:0.213: [CMS-concurrent-mark-start]
 4 2020-09-26T02:53:17.912+ 0800:0.213: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 5 2020-09-26T02:53:17.912+ 0800:0.213: [CMS-concurrent-preclean-start]
 6 2020-09-26T02:53:17.912+ 0800:0.213: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 7 2020-09-26T02:53:17.912+ 0800:0.213: [CMS-concurrent-abortable-preclean-start]
 8 Heap
 9  par new generation   total 92160K, used 33885K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
10   eden space 81920K,  40% used [0x00000000f3800000.0x00000000f5866800.0x00000000f8800000)
11   from space 10240K,   6% used [0x00000000f9200000.0x00000000f92b0f48.0x00000000f9c00000)
12   to   space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
13  concurrent mark-sweep generation total 102400K, used 71680K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
14  Metaspace       used 3047K, capacity 4556K, committed 4864K, reserved 1056768K
15   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

When objects B1 and B2 exceed the threshold of large objects, they will enter the old age directly. Therefore, it can be considered that the average size of large objects entering the old age is 35M. So we have 30 meters left in the old age.
At line 5, 6 and 7 of the code, 60M garbage objects will be generated. At line 9, Eden area is insufficient. At this time, it is judged whether the remaining space of the old age (30M) is larger than the size of all objects of the new generation (60M), and whether it is obvious; Then judge whether the size of the old age (30M) is greater than the average size of the previous promotion object (35M), and whether.

So the Full GC is triggered, and a YoungGC occurs at line 1 in the GC log, and lines 2-7 are CMS OldGC.

CMS trigger OldGC

CMS collector has a parameter – XX: CMSInitiatingOccupancyFraction to control after the old s memory footprint than the proportion, it triggers a CMS. Because the CMS is going to have to leave some space to make sure that during the collection period, the object is going to be old.

Set the following JVM parameters: When the age exceeds 80%, CMS collection is triggered, and the CMS GC thread checks for collection every 2 seconds.

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=15M 
-XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSWaitDuration=2000 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

Run the following code:

public static void main(String[] args) {
    byte[] b3 = new byte[_1M * 30];
    b3 = new byte[_1M * 30];
    b3 = new byte[_1M * 20];

    try {
        Thread.sleep(3000);
    } catch(InterruptedException e) { e.printStackTrace(); }}Copy the code

To view GC logs:

2020-09-26T04:13:52.245+ 0800:2.083: [GC (CMS Initial Mark) [1 CMS-initial-mark: 81920K(102400K)] 86904K(194560K), 0.0006366 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-09-26T04:13:52.245+ 0800:2.084: [CMS-concurrent-mark-start]
2020-09-26T04:13:52.245+ 0800:2.084: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-09-26T04:13:52.245+ 0800:2.084: [CMS-concurrent-preclean-start]
2020-09-26T04:13:52.246+ 0800:2.084: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-09-26T04:13:52.246+ 0800:2.084: [CMS-concurrent-abortable-preclean-start]
Heap
 par new generation   total 92160K, used 6622K [0x00000000f3800000.0x00000000f9c00000.0x00000000f9c00000)
  eden space 81920K,   8% used [0x00000000f3800000.0x00000000f3e77b80.0x00000000f8800000)
  from space 10240K,   0% used [0x00000000f8800000.0x00000000f8800000.0x00000000f9200000)
  to   space 10240K,   0% used [0x00000000f9200000.0x00000000f9200000.0x00000000f9c00000)
 concurrent mark-sweep generation total 102400K, used 81920K [0x00000000f9c00000.0x0000000100000000.0x0000000100000000)
 Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
  class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

As you can see, when the old generation exceeds 80%, a CMS old generation collection is triggered. Note that it is not Full GC, but old generation collection.

Note also that the CMS does not trigger the CMS reclaim immediately if it exceeds 80%. The CMS has an interval set by the -xx :CMSWaitDuration parameter, whose default value is 2000 milliseconds. It can also be seen that the CMS reclaim is triggered after 2 seconds.

G1 Garbage Collection

Let’s take a look at G1 logging for some scenarios. First, set the following JVM parameters:

-Xms200M -Xmx200M -Xmn100M -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=1 
-XX:+UseG1GC -XX:+UnlockExperimentalVMOptions -XX:G1MaxNewSizePercent=50 -XX:G1HeapRegionSize=4M 
-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log
Copy the code

After this setting, the heap memory is 200M, the G1 collector is used, the size of each Region is 4M (note that the N times of the Region is set to 2), there are 50 regions in total, and the largest proportion of the new generation is 50%. In this way, Eden Region is at most 80M, occupying 20 regions. The maximum size of two Survivor zones is 20M, which consists of five regions. And the generational age is set to 1. Note set – XX: G1MaxNewSizePercent parameters, must be set – XX: + UnlockExperimentalVMOptions parameters.

Cenozoic recovery

To create a 50M object, run the following code:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M];

    byte[] b2 = new byte[_1M];
    for (int i = 0; i < 49; i++) {
        b2 = new byte[_1M]; }}Copy the code

To view GC logs:

1 Heap
2  garbage-first heap   total 204800K, used 69632K [0x00000000f3800000.0x00000000f3c00190.0x0000000100000000)
3   region size 4096K, 18 young (73728K), 0 survivors (0K)
4  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
5   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K1 the 2020-09-27T20: 46:49. 585 + 0800:0.197:GC pause (G1 Evacuation Pause) (young), 0.0023352 secs2 []Parallel Time: 1.1 ms.GC Workers: 3 [10]GC Worker Start (ms) :Min: 197.2.Avg: 197.3.Max: 197.3.Diff: 4 [0.1]Ext Root Scanning (ms) :Min: 0.1.Avg: 0.1.Max: 0.2.Diff: 0.1.Sum: 1.2]
 5       [Update RS (ms) :Min: 0.0.Avg: 0.0.Max: 0.0.Diff: 0.0.Sum: 6 [0.0]Processed Buffers: Min: 0.Avg: 0.0.Max: 0.Diff: 0.Sum: 7 [0]Scan RS (ms) :Min: 0.0.Avg: 0.0.Max: 0.0.Diff: 0.0.Sum: 8 [0.0]Code Root Scanning (ms) :Min: 0.0.Avg: 0.0.Max: 0.0.Diff: 0.0.Sum: 9 [0.0]Object Copy (ms) :Min: 0.2.Avg: 0.3.Max: 0.9.Diff: 0.7.Sum: 10 [3.3]Termination (ms) :Min: 0.0.Avg: 0.6.Max: 0.6.Diff: 0.6.Sum: 11 [5.6]Termination Attempts: Min: 1, Avg: 6.0.Max: 12.Diff: 11.Sum12 [60] :GC Worker Other (ms) :Min: 0.0.Avg: 0.0.Max: 0.0.Diff: 0.0.Sum: 13 [0.2]GC Worker Total (ms) :Min: 1.0.Avg: 1.0.Max: 1.1.Diff: 0.1.Sum14 [10.4] :GC Worker End (ms) :Min: 198.3.Avg: 198.3.Max: 198.3.Diff: 15 [0.0]Code Root Fixup: 0.0 ms16 []Code Root Purge: 0.0 ms17 []Clear CT: 0.5 ms18 []Other: 0.7 ms19 []Choose CSet: 0.0 ms20 []Ref Proc: 0.4 ms21 []Ref Enq: 0.0 ms22 []Redirty Cards: 0.3 ms23 []Humongous Register: 0.0 ms24 []Humongous Reclaim: 0.0 ms25 []Free CSet: 0.0 ms26 []Eden: 100.0M(100.0M) - > 0.0B(96.0M) Survivors: 0.0B- > 4096.0K Heap: 100.0M(200.0M) - > 2935.2K(200.0M27 []Times: user=0.00 sys=0.00, real=0.00 secs] 
28 Heap
29  garbage-first heap   total 204800K, used 2935K [0x00000000f3800000.0x00000000f3c00190.0x0000000100000000)
30   region size 4096K, 2 young (8192K), 1 survivors (4096K)
31  Metaspace       used 3047K, capacity 4556K, committed 4864K, reserved 1056768K
32   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

As you can see from line 2, 69632K (68M) was used for the total memory of 204800K (200M). The code creates only 50 MB of objects, but uses 68 MB of memory, which shows that G1 takes up a lot more memory than the other collectors.
According to the log in line 3, the size of the Region is 4096K (4M). The Eden area uses 18 regions with a total size of 73728K (72M). Survivor uses 0 regions.

Run the following code again, and a large number of garbage objects will flood Eden:

public static void main(String[] args) {
    byte[] b1 = new byte[_1M];

    byte[] b2 = new byte[_1M];
    for (int i = 0; i < 71; i++) {
        b2 = new byte[_1M]; }}Copy the code

To view GC logs:

 1 2020-09-27T20:46:49.585+ 0800:0.197: [GC pause (G1 Evacuation Pause) (young), 0.0023352 secs] 2 [Parallel Time: 1.1ms, GC Workers: 10] 3 [GC WorkerStart (ms): Min: 197.2, Avg: 197.3, Max: 197.3, Diff: 0.1]
 4       [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.2]
 5       [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 6 [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0.0] 0] 7 [ScanRS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
 8       [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
 9       [Object Copy (ms): Min: 0.2, Avg: 0.3, Max: 0.9, Diff: 0.7, Sum: 3.3]
10       [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.6, Diff: 0.6, Sum: 5.6] 11 [Termination Attempts: Min: 1, Avg: 6.0, Max: 12, Diff: 5.6] 11, Sum: 60] 12 [GC WorkerOther (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
13       [GC Worker Total (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 10.4]
14       [GC Worker End (ms)5 [Code Root Fixup: 0.0 ms] 16 [Code Root Purge: 0.0 ms] 17 [Clear CT: 0.5 ms] 18 [Other: 0.7 ms] 19 [Choose CSet: 0.0 ms] 20 [Ref Proc: 0.4 ms] 21 [Ref Enq: 0.0 ms] 22 [Redirty Cards: 0.3ms] 23 [Humongous Register: 0.0 ms] 24 [Humongous Reclaim: 0.0 ms] 25 [Free CSet: 0.0 ms] 26 [Eden: 100.0M(100.0M)- > 0.0B(96.0M)Survivors: 0.0 B - > 4096.0 K Heap: 100.0M(200.0M)- > 2935.2K(200.0M)]
27  [Times: user=0.00 sys=0.00, real=0.00 secs] 
28 Heap
29  garbage-first heap   total 204800K, used 2935K [0x00000000f3800000.0x00000000f3c00190.0x0000000100000000)
30   region size 4096K, 2 young (8192K), 1 survivors (4096K)
31  Metaspace       used 3047K, capacity 4556K, committed 4864K, reserved 1056768K
32   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

Line 1 log is what triggers the G1 reclamation, and the G1 Evacuation Pause represents the Evacuation Pause, which is the copying of living objects from one region to another. (young) indicates that this is a GC that occurs in the young generation, that is, the young GC.
Line 2, Parallel Time: 1.1ms: 1.1ms; GC Workers 10: Indicates that the NUMBER of GC Workers is 10.
Lines 3 through 25 are the details of the Young GC.
In line 26, the Eden area is 100M before recycling, occupying 100M; after recycling, it is 96M, occupying 0.0B; Survivor area increases from 0.0B to 4096.0K, occupying a Region; the whole heap is 200M before recycling, occupying 100M, and the whole heap is 200M after recycling. 2935.2 K.
In line 29, 2935K is used for the total heap size of 204800K (200M).
In line 30, the size of each Region is 4096K (4M). After the program ends, Eden Region uses two regions, accounting for 8192K (8M), and Survivor uses one Region, accounting for 4096K (4M).

Hybrid recycling

Mixed collection is triggered when older regions occupy 45% (90M) of heap memory.

Run the following code: Lines 2 to 5 generate 90M objects, and lines 8 to 11 trigger two YoungGC’s. Since the GC age is set to 1, the list of 80M objects will be old after two YoungGC’s.

public static void main(String[] args) {
    List<byte[]> list = new ArrayList<>();
    for (int i = 0; i < 90; i++) {
        list.add(new byte[_1M]);
    }

    // Trigger the Young GC twice
    byte[] b2 = new byte[_1M];
    for (int i = 0; i < 100; i++) {
        b2 = new byte[_1M]; }}Copy the code

Focus on these lines:

 1 2020-09-27T23:16:05.118+ 0800:0.217: [GC pause (G1 Evacuation Pause) (young), 0.0090108 secs]
 2    [Eden: 100.0M(100.0M)- > 0.0B(84.0M)Survivors: 0.0 B - > 16.0 M Heap: 100.0M(200.0M)- > 95.1M(200.0M)] 3 2020-09-27T23:16:05.130+0800: 0.228: [GC] 3 2020-09-27T23:16:05.130+0800: 0.228: [GCpause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0031955 secs]
 4    [Eden: 84.0M(84.0M)- > 0.0B(92.0M)Survivors: 16.0 M - > 8192.0 K Heap: 179.1M(200.0M)- > 124.0M(200.0M)] 5 2020-09-27T23:16:05.136+ 0800:0.235: [GC] 5 2020-09-27T23:16:05.136+ 0800:0.235: [GCpause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0010715 secs]
 6    [Eden: 76.0M(92.0M)- > 0.0B(100.0M)Survivors: 8192.0 K - > 0.0 B Heap: 200.0M(200.0M)- > 128.0M(200.0M)]
 7  [Times: user=0.00 sys=0.00, real=0.00 secs] 
 8 2020-09-27T23:16:05.137+ 0800:0.236: [GC concurrent-root-region-scan-start]
 9 2020-09-27T23:16:05.137+ 0800:0.236: [GC concurrent-root-region-scan-end, 0.0000095 secs]
10 2020-09-27T23:16:05.137+ 0800:0.236: [GC concurrent-mark-start]
11 2020-09-27T23:16:05.138+ 0800:0.237: [GC concurrent-mark-end, 0.0012656 secs]
12 2020-09-27T23:16:05.138+ 0800:0.237: [GC remark 2020-09-27T23:16:05.139+ 0800:0.237: [Finalize Marking, 0.0001289 secs] 2020-09-27T23:16:05.139+ 0800:0.238: [GC ref-proc, 0.0005058 secs] 2020-09-27T23:16:05.139+ 0800:0.238: [Unloading, 0.0004047 secs], 0.0013203 secs]
13  [Times: user=0.00 sys=0.00, real=0.00 secs] 
14 2020-09-27T23:16:05.140+ 0800:0.239: [GC cleanup 132M->132M(200M), 0.0005312 secs]
15  [Times: user=0.00 sys=0.00, real=0.00 secs] 
16 Heap
17  garbage-first heap   total 204800K, used 135168K [0x00000000f3800000.0x00000000f3c00190.0x0000000100000000)
18   region size 4096K, 2 young (8192K), 0 survivors (0K)
19  Metaspace       used 3048K, capacity 4556K, committed 4864K, reserved 1056768K
20   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

Line 1 log, trigger YoungGC because Eden block is full
In line 2 of the log, the Eden Region occupies 100M (25 regions) before the recovery and 100M is used. After the recovery, the Eden Region occupies 84M (21 regions) and 0M is used. The Survivor Region occupies 16M (4 regions). The heap space occupies 95.1M.
(line 3) If Eden exhausted, YoungGC is triggered, and To Survivor exhausted (to-space Exhausted), objects surviving in the new generation will be copied To the old age.
In line 4 of the log, before the second YoungGC, the Eden area occupies 84M, 84M is used, 92M (23 regions) is recovered, and 8192.0K (2 regions) is Survivor area. The heap space occupies 124M.
In line 5, the G1 mixed collection is triggered because the old Region exceeds 45% of the heap space. The mixed collection will collect the new generation + old generation, so YoungGC is executed first and initial-mark is made.
Lines 8 and 9 of the log, scan the GC Roots partition.
Lines 10, 11 log, concurrent marking phase.
Line 12 log, final marking phase.
Line 14, log, clean up the recycle phase.

As can be seen from the changes in Eden zone above, the ratio between Eden zone and Survivor zone is constantly changing, but the total size of the new generation will not exceed the set percentage (60% by default).

G1 Full GC

Run the following code:

public static void main(String[] args) {
    List<byte[]> list = new ArrayList<>();
    for (int i = 0; i < 70; i++) {
        list.add(new byte[_1M]);
    }

    // Trigger the Young GC, and the 70M objects of the list will enter the old age
    byte[] b2 = new byte[_1M];
    for (int i = 0; i < 10; i++) {
        b2 = new byte[_1M];
    }

    list = new ArrayList<>(); // The previous 70M becomes garbage
    for (int i = 0; i < 70; i++) {
        list.add(new byte[_1M]);
    }

    for (int i = 0; i < 70; i++) { // Fill the Eden area again, the old age will be filled, triggering Full GC
        b2 = new byte[_1M]; }}Copy the code

Look mainly at this section of the log:

 1 2020-09-27T22:07:58.115+ 0800:0.212: [Full GC (Allocation Failure)2020-09-27T22:07:58.124+ 0800:0.221: [GC concurrent-mark-start] 2 200M-> 200M(200M), 0.0104677 secs]
 3    [Eden: 0.0B(100.0M)- > 0.0B(100.0M)Survivors: 0.0 - > 0.0 B B Heap: 200.0M(200.0M)- > 71.6M(200.0M)], [Metaspace: 3045K->3045K(1056768K)]
 4  [Times: user=0.00 sys=0.00, real=0.01 secs] 
 5 2020-09-27T22:07:58.126+ 0800:0.223: [GC concurrent-mark-abort]
 6 Heap
 7  garbage-first heap   total 204800K, used 130627K [0x00000000f3800000.0x00000000f3c00190.0x0000000100000000)
 8   region size 4096K, 15 young (61440K), 0 survivors (0K)
 9  Metaspace       used 3052K, capacity 4556K, committed 4864K, reserved 1056768K
10   class space    used 322K.capacity 392K.committed 512K.reserved 1048576K
Copy the code

Look at line 1 of the log, Full GC (Allocation Failure) : the result is Full GC because the old generation cannot be released. GC concurrent-mark-start: starts the concurrent marking, which is immediately switched to stop the system program because it fails, and then marks, cleans, and compresses with a single thread.

G1 GC logs for details

Detailed analysis about various G1 recovery log reference: www.cnblogs.com/javaadu/p/1…

The cause of the GC trigger

In the previous GC logs, parentheses show the reasons for triggering GC, such as CMS Initial Mark, Allocation Failure, and many other reasons that can cause GC. And different garbage collectors can trigger GC at different times and for different reasons, but in general, some of the situations mentioned earlier lead to YoungGC or FullGC.

#include "precompiled.hpp"
#include "gc/shared/gcCause.hpp"

const char* GCCause::to_string(GCCause::Cause cause) {
  switch (cause) {
    case _java_lang_system_gc:
      return "System.gc()";

    case _full_gc_alot:
      return "FullGCAlot";

    case _scavenge_alot:
      return "ScavengeAlot";

    case _allocation_profiler:
      return "Allocation Profiler";

    case _jvmti_force_gc:
      return "JvmtiEnv ForceGarbageCollection";

    case _gc_locker:
      return "GCLocker Initiated GC";

    case _heap_inspection:
      return "Heap Inspection Initiated GC";

    case _heap_dump:
      return "Heap Dump Initiated GC";

    case _wb_young_gc:
      return "WhiteBox Initiated Young GC";

    case _wb_conc_mark:
      return "WhiteBox Initiated Concurrent Mark";

    case _wb_full_gc:
      return "WhiteBox Initiated Full GC";

    case _update_allocation_context_stats_inc:
    case _update_allocation_context_stats_full:
      return "Update Allocation Context Stats";

    case _no_gc:
      return "No GC";

    case _allocation_failure:
      return "Allocation Failure";

    case _tenured_generation_full:
      return "Tenured Generation Full";

    case _metadata_GC_threshold:
      return "Metadata GC Threshold";

    case _metadata_GC_clear_soft_refs:
      return "Metadata GC Clear Soft References";

    case _cms_generation_full:
      return "CMS Generation Full";

    case _cms_initial_mark:
      return "CMS Initial Mark";

    case _cms_final_remark:
      return "CMS Final Remark";

    case _cms_concurrent_mark:
      return "CMS Concurrent Mark";

    case _old_generation_expanded_on_last_scavenge:
      return "Old Generation Expanded On Last Scavenge";

    case _old_generation_too_full_to_scavenge:
      return "Old Generation Too Full To Scavenge";

    case _adaptive_size_policy:
      return "Ergonomics";

    case _g1_inc_collection_pause:
      return "G1 Evacuation Pause";

    case _g1_humongous_allocation:
      return "G1 Humongous Allocation";

    case _dcmd_gc_run:
      return "Diagnostic Command";

    case _last_gc_cause:
      return "ILLEGAL VALUE - last gc cause - ILLEGAL VALUE";

    default:
      return "unknown GCCause";
  }
  ShouldNotReachHere();
}
Copy the code

mo4tech.com (Moment For Technology) is a global community with thousands techies from across the global hang out!Passionate technologists, be it gadget freaks, tech enthusiasts, coders, technopreneurs, or CIOs, you would find them all here.

JVM performance tuning (3) – Analyze garbage collection policies through GC logs

Memory Settings

Setting up JVM memory

Outputting GC Logs

Setting GC Parameters

View default parameters

The GC log

GC when the JVM exits

Memory allocation and reclamation policies

The object is first allocated to the Eden region

Eden block full trigger YoungGC

Large objects will go straight to the old age

Long-lived objects will enter the old age

Dynamic object age determination

Unable to enter Survivor zone directly into the old age

Guarantee principle of old chronospatial allocation

CMS trigger OldGC

G1 Garbage Collection

Cenozoic recovery

Hybrid recycling

G1 Full GC

G1 GC logs for details

The cause of the GC trigger

conclusion

Memory Parameter Settings

Garbage collection trigger time

JVM performance tuning (3) – Analyze garbage collection policies through GC logs

Memory Settings

Setting up JVM memory

Outputting GC Logs

Setting GC Parameters

View default parameters

The GC log

GC when the JVM exits

Memory allocation and reclamation policies

The object is first allocated to the Eden region

Eden block full trigger YoungGC

Large objects will go straight to the old age

Long-lived objects will enter the old age

Dynamic object age determination

Unable to enter Survivor zone directly into the old age

Guarantee principle of old chronospatial allocation

CMS trigger OldGC

G1 Garbage Collection

Cenozoic recovery

Hybrid recycling

G1 Full GC

G1 GC logs for details

The cause of the GC trigger

conclusion

Memory Parameter Settings

Garbage collection trigger time

Related Posts

Have you learned about Python iterators and generators?

Architecture practices for small and medium-sized r&d teams: a collection of gadgets

2020 Spring Boot distributed lock implementation