Illustrated JVM experiments – Conditions that trigger FullGC

1. There are too many living objects for the young generation to let go of the old generation

01. Sample code

public class DemoTest1 {
    public static void main(String[] args) {
        byte[] array1 = new byte[4 * 1024 * 1024];
        array1 = null;

        byte[] array2 = new byte[2 * 1024 * 1024];
        byte[] array3 = new byte[2 * 1024 * 1024];
        byte[] array4 = new byte[2 * 1024 * 1024];
        byte[] array5 = new byte[128 * 1024];

        byte[] array6 = new byte[2 * 1024 * 1024];

    }

Copy the code

02. Start JVM parameters

-XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:SurvivorRatio=8  -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=3145728 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log
Copy the code

Among them, the parameter – XX: PretenureSizeThreshold, parameters to set up the large object threshold to 3 MB, which is more than 3 MB, is directly into old age.

The large object size is 3MB. Once the object size exceeds 3MB, it does not enter the new generation, but directly into the old generation.

Start command:

java  -jar -XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:SurvivorRatio=8  -XX:MaxTenuringThre
shold=15 -XX:PretenureSizeThreshold=3145728 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log jvm-demo.jar
Copy the code

03. GC logs

After startup, you get the following GC log:

Java HotSpot(TM) 64-Bit Server VM (25.151-b12) for windows-amd64 JRE (1.8.0_151-b12), built on Sep  5 2017 19:33:46 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16703268k(7458748k free), swap 23781156k(9784196k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=3145728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.174: [GC (Allocation Failure) 0.174: [ParNew (promotion failed): 7457K->8328K(9216K), 0.0046949 secs]
0.179: [CMS: 8194K->6962K(10240K), 0.0033396 secs] 11553K->6962K(19456K), [Metaspace: 2970K->2970K(1056768K)], 0.0089224 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 9216K, used 2130K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  26% used [0x00000000fec00000, 0x00000000fee14930, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 6962K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2976K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 330K, capacity 386K, committed 512K, reserved 1048576K

Copy the code

04. Analyze GC logs

Let’s start with the following code:

 byte[] array1 = new byte[4 * 1024 * 1024];
        array1 = null;
Copy the code

This line of code directly allocates a large 4MB object, at which point the object goes straight to the old age, and Array1 no longer references the object.

In this case, the memory allocation is as follows:

This is followed by the following code

byte[] array2 = new byte[2 * 1024 * 1024];
        byte[] array3 = new byte[2 * 1024 * 1024];
        byte[] array4 = new byte[2 * 1024 * 1024];
        byte[] array5 = new byte[128 * 1024];
Copy the code

Four arrays are allocated consecutively, among which three are 2MB and one is 128KB, as shown in the figure below. All of them will enter Eden area.

The following code is then executed: byte[] array6 = new byte[2 * 1024 * 1024]; . Is there room for 2MB objects at this point?

That’s impossible, because there’s no room in Eden anymore. So a Young GC is fired directly at this point.

Let’s look at the following GC log:

0.174: [GC (Allocation Failure) 0.174: [ParNew (promotion failed): 7457K->8328K(9216K), 0.0046949 secs]
Copy the code

This line of log shows that the Eden field originally had more than 7000 KB of objects, but none of them could be reclaimed because the above arrays were referenced by variables.

So at this point, we would definitely put these objects directly into the old age, but we already have a 4MB array in the old age, can we still put three 2MB arrays and one 128KB array?

Obviously not, at this time will exceed the old 10MB size.

So look at the GC log at this point:

0.179: [CMS: 8194K->6962K(10240K), 0.0033396 secs] 11553K->6962K(19456K), [Metaspace: 2970K->2970K(1056768K)], 0.0089224 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Copy the code

At this point, the CMS garbage collector’s Full GC is performed, which is essentially an Old GC for the Old years, usually associated with a Young GC, and triggers a metadata section (permanent generation) GC.

The Young GC was triggered before the CMS Full GC, so you can see that the Young GC is already in place, and then the Old GC is executed for the Old generation, which is the following log:

CMS: 8194 k - > 6962 k (10240 k), 0.0033396 secs

So what we see here is that in the old days we went from around 8MB of object occupancy to around 6MB of object occupancy. How does that happen?

Very simply, two 2MB arrays must have been placed in the old age after the Young GC, as shown below.

The CMS Full GC will be triggered if you continue to put a 2MB array and a 128KB array into the old age.

It then recycles one of the 4MB arrays because it is no longer referenced, as shown below.

CMS: 8194K->6962K(10240K), 0.0033396 secs, it has changed from 8MB to 6MB, as shown in the figure above.

Finally, after the CMS Full GC is complete, the objects of the young generation are in the old age, and the last line of code allocates the 2MB array in the young generation, as shown in the figure below.

05. Conclusion

This is a case of triggering the old generation GC, where the young generation has too many surviving objects to fit the old generation, and the CMS Full GC is triggered.

2. The available space of the old age is less than the average size of objects promoted to the old age after the previous Young GC

01. Sample code

public class DemoTest1 {
    public static void main(String[] args) {
        byte[] array1 = new byte[1 * 1024 * 1024];
        array1 = null;
        byte[] array2 = new byte[1 * 1024 * 1024];
        array2 = null;
        byte[] array3 = new byte[1 * 1024 * 1024];
        array3 = null;
        byte[] array4 = new byte[1 * 1024 * 1024];// Trigger YGC 1MB 1

        array1 = new byte[1 * 1024 * 1024];
        array1 = null;
        array2 = new byte[1 * 1024 * 1024];
        array2 = null;
        array3 = new byte[1 * 1024 * 1024];// Trigger YGC Y 1MB O 1MB 2
        array3 = null;

        byte[] array5 = new byte[1 * 1024 * 1024];// Y 2MB O 1MB
        array1 = new byte[1 * 1024 * 1024];// Y 3MB
        array1 = null;
        array2 = new byte[1 * 1024 * 1024];// Y 1MB O 2MB YGC 3
        
        array2 = null;
        array3 = new byte[1 * 1024 * 1024];//Y 2MB O 2MB
        array3 = null;
        byte[] array6 = new byte[1 * 1024 * 1024];//Y 3MB O 2MB
        array1 = new byte[1 * 1024 * 1024];//Y 1MB O 3MB YGC 4
        
        array1 = null;
        array2 = new byte[1 * 1024 * 1024];//Y 2MB
        array2 = null;
        array3 = new byte[1 * 1024 * 1024];//Y 3MB
        array3 = null;
        byte[] array7 = new byte[1 * 1024 * 1024];//YGC 5}}Copy the code

02. Start JVM parameters

-XX:NewSize=5M -XX:MaxNewSize=5M -XX:InitialHeapSize=10M -XX:MaxHeapSize=10M -XX:SurvivorRatio=8  -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=2M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log
Copy the code

Among them, the parameter – XX: PretenureSizeThreshold, parameters to set up the large object threshold of 2 MB, which is more than 2 MB, is directly into old age.

The large object size is 3MB. Once the object size exceeds 3MB, it does not enter the new generation, but directly into the old generation.

Start command:

java  -jar -XX:NewSize=5M -XX:MaxNewSize=5M -XX:InitialHeapSize=10M -XX:MaxHeapSize=10M -XX:SurvivorRatio=8  -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=2M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log jvm-demo.jar
Copy the code

03. GC logs

After startup, you get the following GC log:

The old s

The young generation

Java HotSpot(TM) 64-Bit Server VM (25.151-b12) for windows-amd64 JRE (1.8.0_151-b12), built on Sep  5 2017 19:33:46 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16703268k(7221016k free), swap 23781156k(8613656k free)
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:MaxTenuringThreshold=15 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=2097152 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.121: [GC (Allocation Failure) 0.121: [ParNew: 3155K->512K(4608K), 0.0041165 secs] 3155K->766K(9728K), 0.0042644 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.125: [GC (Allocation Failure) 0.125: [ParNew: 3663K->0K(4608K), 0.0016667 secs] 3917K->1732K(9728K), 0.0017448 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.127: [GC (Allocation Failure) 0.127: [ParNew: 3142K->0K(4608K), 0.0013221 secs] 4875K->2756K(9728K), 0.0013592 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.129: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2756K(5120K)] 4878K(9728K), 0.0004498 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.129: [CMS-concurrent-mark-start]
0.130: [GC (Allocation Failure) 0.130: [ParNew: 3146K->0K(4608K), 0.0005869 secs] 5902K->2756K(9728K), 0.0006362 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.131: [GC (Allocation Failure) 0.131: [ParNew: 3148K->0K(4608K), 0.0007974 secs] 5904K->3780K(9728K), 0.0008262 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 4608K, used 2207K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  53% used [0x00000000ff600000, 0x00000000ff827f38, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
  to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
 concurrent mark-sweep generation total 5120K, used 3780K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2976K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 330K, capacity 386K, committed 512K, reserved 1048576K

Copy the code

04. Analyze GC logs

(1) code block 1

Let’s start with the following code:

  byte[] array1 = new byte[1 * 1024 * 1024];
  array1 = null;
  byte[] array2 = new byte[1 * 1024 * 1024];
  array2 = null;
  byte[] array3 = new byte[1 * 1024 * 1024];
  array3 = null;
  byte[] array4 = new byte[1 * 1024 * 1024];
Copy the code

This code directly allocates four 1MB arrays, and on the fourth array, YGC is triggered because the new generation is out of memory.

In this case, the memory allocation is as follows:

The corresponding GC logs are as follows:

0.121: [GC (Allocation Failure) 0.121: [ParNew: 3155K->512K(4608K), 0.0041165 secs] 3155K->766K(9728K), 0.0042644 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Copy the code

At this point, you can see that there are only 512KB objects left in the new generation, and this strange 512KB object has entered the Survivor From zone.

So where does an array object of size 1MB go? Definitely not this weird 512KB object.

This 1MB array must be ready to enter the Survivor From zone in the first place, but with the JVM parameters we set, only 0.5MB is clearly not enough to allocate. According to the JVM YoungGC rule, the Survivor zone will not hold any objects that survive after GC and will go straight to the old age.

So, 1MB array objects are straight into the old days.

At this point, the memory allocation is as follows:

(2). Block 2

And then there’s this code:

 array1 = new byte[1 * 1024 * 1024];
 array1 = null;
 array2 = new byte[1 * 1024 * 1024];
 array2 = null;
 array3 = new byte[1 * 1024 * 1024];
Copy the code

Again, three 1MB array objects are created and YoungGC is triggered once;

The corresponding GC logs are as follows:

0.125: [GC (Allocation Failure) 0.125: [ParNew: 3663K->0K(4608K), 0.0016667 secs] 3917K->1732K(9728K), 0.0017448 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Copy the code

At this point, after the Young GC, the new generation becomes 0KB, so where does the surviving 1MB array object go?

This 1MB array must be ready to enter the Survivor From zone in the first place, but with the JVM parameters we set, only 0.5MB is clearly not enough to allocate. According to the JVM YoungGC rule, the Survivor zone will not hold any objects that survive after GC and will go straight to the old age.

So, 1MB array objects are straight into the old days.

The unknown object 512KB that we saw before also entered the old age, and the memory allocation was as follows:

(3) code block 3

array3 = null;
byte[] array5 = new byte[1 * 1024 * 1024];
array1 = new byte[1 * 1024 * 1024];
array1 = null;
array2 = new byte[1 * 1024 * 1024];
Copy the code

Again, three 1MB array objects are created and YoungGC is triggered once;

The corresponding GC log is as follows:

0.127: [GC (Allocation Failure) 0.127: [ParNew: 3142K->0K(4608K), 0.0013221 secs] 4875K->2756K(9728K), 0.0013592 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Copy the code

In this case, the memory allocation is as follows:

Code block 4

array2 = null;
array3 = new byte[1 * 1024 * 1024];//Y 2MB O 2MB
array3 = null;
byte[] array6 = new byte[1 * 1024 * 1024];
array1 = new byte[1 * 1024 * 1024];
Copy the code

Again, three 1MB array objects are created and YoungGC is triggered once; And here, the CMS Old GC is triggered once before the Young GC is triggered, if the available space of the Old GC is less than the average size of the objects promoted from the previous Young GC. At this point the Cenozoic became 10 kilobytes in size

The corresponding GC log is as follows:

0.129: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2756K(5120K)] 4878K(9728K), 0.0004498 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.129: [CMS-concurrent-mark-start]
0.130: [GC (Allocation Failure) 0.130: [ParNew: 3146K->0K(4608K), 0.0005869 secs] 5902K->2756K(9728K), 0.0006362 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Copy the code

In this case, the memory allocation is as follows:

Code block 5

array1 = null;
array2 = new byte[1 * 1024 * 1024];//Y 2MB
array2 = null;
array3 = new byte[1 * 1024 * 1024];//Y 3MB
array3 = null;
byte[] array7 = new byte[1 * 1024 * 1024];
Copy the code

YoungGC = 0; YoungGC = 0; YoungGC = 0;

The corresponding GC log is as follows:

0.131: [GC (Allocation Failure) 0.131: [ParNew: 3148K->0K(4608K), 0.0007974 secs] 5904K->3780K(9728K), 0.0008262 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Copy the code

In this case, the memory allocation is as follows:

(6)

We can also verify the above hypothesis with the following GC heap memory log:

At this point, the new generation is using 53% of the size, we have a 1MB array, and there may be some unknown objects.

In the old days it used about 3MB of space, which is probably the object in the image above.

Heap
 par new generation   total 4608K, used 2207K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  53% used [0x00000000ff600000, 0x00000000ff827f38, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
  to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
 concurrent mark-sweep generation total 5120K, used 3780K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2976K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 330K, capacity 386K, committed 512K, reserved 1048576K
Copy the code

3. Several conditions that trigger the Full GC

First: the size of the available memory in the old age is smaller than the size of all objects in the new generation. If the space guarantee parameter is not enabled, the Full GC will be triggered directly, so the general space guarantee parameter will be turned on. Note: -xx: -handlepromotionfailure has been removed since jDK1.8

Second, the available memory of the old age is smaller than the average size of objects entering the old age after previous generation GC, so the Full GC will be carried out in advance.

Third, if there are more surviving objects than Survivor after Minor GC, then the old age is out of memory.

All of the above causes the old Full GC.

Fourth: is “- XX: CMSInitiatingOccupancyFaction” parameter,

Full GC is also triggered automatically if the available memory of the old generation is larger than the average size of objects that have entered the old generation after the previous generation GC, but the memory used by the old generation exceeds the ratio specified by this parameter. The default 92%