The GC log

Hands-on simulation of frequent Young GC scenarios

JVM parameters are configured as follows:

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

Parameter Description:

  • -xx :NewSize=5242880 the initial new generation size is 5MB
  • -xx :MaxNewSize=5242880 new generation maximum size of 5MB
  • -xx :InitialHeapSize=10485760 the InitialHeapSize is 10MB
  • -xx :MaxHeapSize=10485760 the maximum size of the heap is 10MB
  • – XX: PretenureSizeThreshold = 10485760 large object threshold 10 MB

-XX:+UseParNewGC -XX:+UseConcMarkSweepGC

The new generation adopts ParNew garbage collector, and the old generation adopts CMS garbage collector

  • -xx :+PrintGCDetails: Prints detailed GC logs
  • -xx :+PrintGCTimeStamps Prints the time of each GC
  • -xloggc :gc.log Writes GC logs to disk files

Heap memory:

  • The new generation 5 MB
    • Eden 4MB
    • Survivor1 0.5 MB
    • Survivor2 0.5 MB
  • Old age 5 MB

Sample program:

    public static void main(String[] args) {
        // create 3 arrays in a row, each 1MB in size
        byte[] array1 = new byte[1024 * 1024];
        array1 = new byte[1024 * 1024];
        array1 = new byte[1024 * 1024];
        // Three arrays become junk objects
        array1 = null;

        // Create an array with a size of 2MB
        byte[] array2=new byte[2*1024*1024];

    }
Copy the code

After executing the main method, the resulting GC log reads:

OpenJDK 64-bit Server VM (25.252-b09) for Windows-AMd64 JRE (1.8.0_252-b09), Built on Apr 22 2020 09:32:45 by "Jenkins" with MS VC++ 12.0 (VS2013) Memory: 4k page, physical 8045256k(1927624k free), swap 17724284k(4980548k free) CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -xx :+UseParNewGC 0.216: [Allocation Failure (GC) 0.218: [ParNew: 3489K->512K, 0.0030149secs] 3489K->1851K, 0.0030149secs] [Times: Sys =0.00, real=0.00 secs] 0.222: [GC (Allocation Failure) 0.222: [ParNew: [Times: 0.002028k, 0.002028k] [Times: 0.002028k, 0.002028k] User =0.00 sys=0.00, real=0.00 SECS] Heap PAR New Generation Total 4608K, Used 2192K [0x00000000FF600000, 0x00000000ffb00000, 0x00000000ffb00000) eden space 4096K, 53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000) from space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000) to space 512K, 0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000) concurrent mark-sweep generation total 5120K, used 1848K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000) Metaspace used 3165K, capacity 4496K, committed 4864K, reserved 1056768K class space used 328K, capacity 388K, committed 512K, reserved 1048576KCopy the code

Young GC log analysis

CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
Copy the code

The JVM parameters set by the programmer and default

0.216: [GC (Allocation Failure) 0.218: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Copy the code

Allocation Failure (GC) : Allocating memory to an object fails

0.216: Garbage collection occurred after the system ran 216ms

ParNew: 3489 k – > 512 k (4608 k), 0.0030149 secs

  • ParNew: Garbage collector adopted by the new generation GC

  • 3489K->512K(4608K)

    • 4608K: available memory of the new generation (4.5MB=1024 x 4.5). Eden 4MB+ Survivor 0.5MB =4.5MB

    • 3489K->512K

      A GC was performed on the young generation, 3489KB was used before GC, and only 512KB of objects survived after GC

  • 0.0030149 secs

    This GC takes about 3ms and only reclaims about 3MB of objects

3489 k – > 1851 k (9728 k), 0.0053277 secs

This is the entire Java heap

The total free space of the Java heap is 9728K (4.5MB for new generation + 5MB for old generation),

The heap used 3489K of memory before GC, and the Java heap used 574KB after GC

[Times: user=0.00 sys=0.00, real=0.00 secs]

Local GC consumes time

The smallest unit here is two decimal places, but everything here is 0.00 secs, which means that the gc took a few milliseconds, so in seconds, it’s almost zero.

Heap memory usage after GC

Heap
 par new generation total 4608K, used 2192K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K, 53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K, 0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1848K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3165K, capacity 4496K, committed 4864K, reserved 1056768K
  class space used 328K, capacity 388K, committed 512K, reserved 1048576K
Copy the code

This log is the heap memory usage that is printed when the JVM exits.

Heap
 par new generation total 4608K, used 2192K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K, 53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K, 0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
Copy the code

Heap par new generation total 4608K, used 2192K

The “ParNew” garbage collector is responsible for a young generation of 4608K (4.5MB) of available memory, currently using 2192KB

A 2MB array is then created

 eden space 4096K, 53% used [0x00000000ff600000, 0x00000000ff8240c0, 0x00000000ffa00000)
  from space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K, 0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
Copy the code

Eden area 4MB memory, 53% used

From Survivor zone 512KB, 100%? Not ah

 concurrent mark-sweep generation total 5120K, used 1848K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3165K, capacity 4496K, committed 4864K, reserved 1056768K
  class space used 328K, capacity 388K, committed 512K, reserved 1048576K
Copy the code

The Concurrent Mark-sweep garbage collector, also known as the CMS garbage collector, manages a total of 5MB of old-age memory space, using 1848KB at this time. We don’t need to know what 1848KB of memory is just yet

The Metaspace metadata space and the Class space hold some Class information and some constant pools and things like that.

Java8 has eliminated PermGen. MetaSpace was replaced, and the method area moved to MetaSpace after java8. Jdk8 starts to put class metadata into the native heap, called MetaSpace. In theory, MetaSpace can be as large as the remaining amount of local memory. Of course, we can't increase MetaSpace indefinitely. You need to specify the MetaSpace area size with -xx :MaxMetaSpaceSize. The MetaSpace consists of one or more Virtual Spaces. The MetaSpace consists of one or more Virtual Spaces. The MetaSpace consists of one or more Virtual Spaces. Virtual space is the continuous storage space of the operating system. Virtual space is allocated on demand. When allocated, virtual Spaces are reserved for the operating system, but not committed. The reserved space of MetaSpace is the size of the total virtual space. The smallest unit of allocation for a virtual space is the MetaChunk (or Chunk). When a new Chunk is allocated to the virtual space, the committed memory space associated with the Chunk is committed. MetaSpace committed refers to the committed space of all chunks. Each Chunk occupies a different space. When a Class Loader is gc, all chunks associated with it are freed. The freed chunks are maintained in a global free array. MetaSpace's capacity refers to the space occupied by all chunks that are not released. The COMMITTED GC log is 4864K, capacity4486K. A portion of the Chunk has been released, indicating that some classloaders have been reclaimedCopy the code

Start to simulate the scene of the object entering the old age

The time when the object enters the old age

  1. Avoid 15 GC and enter the old age after reaching the age of 15
  2. Dynamic age determination rule, if Survivor area, age 1+ age 2+… + The size of objects with age n exceeds 50% of Suvivor space, then all objects with age above N enter the old age (not necessarily 15 years old)
  3. If after GC, there are too many surviving objects for the Survivor region, the object enters the old age
  4. Large objects go directly to the old age (in G1, into a Region dedicated to large objects)

Simulated dynamic age determination rule (objects enter old age)

The JVM parameter

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

10MB for the new generation, 8MB for Eden and 1MB for each Survivor.

The total size of the Java heap is 20MB, with 10MB for older generations

Large objects must exceed 10MB to go straight to the old age

The subjects are 15 years old and go straight into old age

The test code

    public static void main(String[] args) {
        
        byte[] array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB

        array1 = null;

        byte[] array2 = new byte[128 * 1024];// 128KB

        byte[] array3 = new byte[2*1024 * 1024]; // 2MB
    }
Copy the code

The GC log

OpenJDK 64-Bit Server VM (25.252-b09) for windows-amd64 JRE (1.8.0_252-b09), built on Apr 22 2020 09:32:45 by "jenkins" with MS VC++ 12.0 (VS2013)
Memory: 4k page, physical 8045256k(870552k free), swap 18055740k(2357196k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.153: [GC (Allocation Failure) 0.184: [ParNew: [Times: user=0.00 sys=0.00, real= 0.00] [Times: user=0.00 sys=0.00, real= 0.00]
Heap
 par new generation total 9216K, used 3039K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K, 27% used [0x00000000fec00000, 0x00000000fee29808, 0x00000000ff400000)
  from space 1024K, 80% used [0x00000000ff500000, 0x00000000ff5ce600, 0x00000000ff600000)
  to   space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3238K, capacity 4496K, committed 4864K, reserved 1056768K
  class space used 338K, capacity 388K, committed 512K, reserved 1048576K
Copy the code

0.291: [Allocation Failure (GC) 0.292: [ParNew: [Times: user=0.00 sys=0.00, real= 0.03secs] [Times: user=0.00 sys=0.00, real= 0.03secs]

byte[] array3 = new byte[2*1024 * 1024]; YoungGC is triggered when the 2MB code tries to allocate 2MB memory and finds that the Eden area is running out of memory, marking the survivable object and copying it to the From Survivor area.

9216K is the available memory of the new generation =Eden 8MB+ the free Survivor zone (From Survivor zone) 1MB=9MB

6763K=6MB byte array object +128KB array object + other objects 491 KB.

6MB byte array object +128KB array object =6272 KB

491 KB + 128KB=619KB objects, smaller than 854KB objects, but close enough.

Heap par new generation total 9216K, used 5402K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000) eden space 8192K, 55% used [0x00000000fec00000, 0x00000000ff071048, 0x00000000ff400000) from space 1024K, 83% used [0x00000000ff500000, 0x00000000ff5d5838, 0x00000000ff600000) to space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)

Eden Space 8192K, 55% = 4.4MB

From space 1024K, 83% about 854KB.

Sample code refinement

 public static void main(String[] args) {
        byte[] array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB
        array1 = new byte[2 * 1024 * 1024];// 2MB

        array1 = null;

        byte[] array2 = new byte[128 * 1024];// 128KB

        byte[] array3 = new byte[2 * 1024 * 1024]; // 2MB

        array3 = new byte[2 * 1024 * 1024]; // 2MB
        array3 = new byte[2 * 1024 * 1024]; // 2MB
        array3 = new byte[128 * 1024];// 128KB
        array3 = null;

        byte[] array4 = new byte[2 * 1024 * 1024];//2MB
    }
Copy the code

With the code perfected, we can trigger a second Young GC

        array3 = new byte[2 * 1024 * 1024]; // 2MB
        array3 = new byte[2 * 1024 * 1024]; // 2MB
 		array3 = new byte[128 * 1024];// 128KB
        array3 = null;
Copy the code
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 8045256k(2183480k free), swap 18224968k(2626948k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.111: [GC (Allocation Failure) 0.111: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.112: [ParNew: 7004K->0K(9216K), 0.0025875secs] 7004K->680K(19456K), 0.0026298secs] [Times: User sys = = 0.00 0.00, real = 0.00 secs]
Heap
 par new generation total 9216K, used 2212K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K, 27% used [0x00000000fec00000, 0x00000000fee290e0, 0x00000000ff400000)
  from space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K, 0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 concurrent mark-sweep generation total 10240K, used 680K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2603K, capacity 4486K, committed 4864K, reserved 1056768K
  class space used 288K, capacity 386K, committed 512K, reserved 1048576K
Copy the code

The dynamic age rule is triggered, and the surviving object From the Survivor zone enters the old age

When the age of the simulated object is 15, it will enter the old age directly

 for (int i = 0; i < 15; i++) {
            byte[] temp = new byte[7 * 1024 * 1024];
            temp = null;
            if (i == 0) {
                byte[] array1 = new byte[800 * 1024]; }}Copy the code
OpenJDK 64-Bit Server VM (25.252-b09) for windows-amd64 JRE (1.8.0_252-b09), built on Apr 22 2020 09:32:45 by "jenkins" with MS VC++ 12.0 (VS2013)
Memory: 4k page, physical 8045256k(1311456k free), swap 19123728k(2824324k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.135: [Allocation Failure (GC) 0.135: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.141: [GC (Allocation Failure) 0.141: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.144: [GC (Allocation Failure) 0.144: [ParNew: [Times: sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.145: [Allocation Failure (GC) 0.145: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.147: [GC (Allocation Failure) 0.147: [ParNew: [Times: user= 0.03sys =0.00, real=0.00 secs] [Times: user= 0.03sys =0.00, real=0.00 secs]
0.148: [GC (Allocation Failure) 0.148: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.149: [GC (Allocation Failure) 0.149: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.151: [Allocation Failure (GC) 0.151: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.152: [Allocation Failure (GC) 0.152: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.153: [GC (Allocation Failure) 0.153: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.154: [GC (Allocation Failure) 0.154: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.155: [GC (Allocation Failure) 0.155: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.157: [Allocation Failure (GC) 0.157: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.158: [GC (Allocation Failure) 0.158: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.159: [Allocation Failure (GC) 0.159: [ParNew: [Times: user=0.00 sys=0.00, real=0.00 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 par new generation total 9216K, used 7394K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K, 89% used [0x00000000fec00000, 0x00000000ff331a38, 0x00000000ff400000)
  from space 1024K, 2% used [0x00000000ff500000, 0x00000000ff5070e0, 0x00000000ff600000)
  to   space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 588K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3270K, capacity 4496K, committed 4864K, reserved 1056768K
  class space used 343K, capacity 388K, committed 512K, reserved 1048576K

Copy the code

After simulating the Young GC, the object cannot be placed into Survivor and enters the old age directly