JVM-GC log detailed analysis

JVM-GC log detailed analysis

1. Print GC log parameters

1.3 basic JVM parameters
Parameter exampleDescription
-verbose:gcConsole print GC parameters
-Xms20MInitial heap size 20M
-Xmx20MThe maximum heap size is 20M. Generally, the values of - Xms and - Xmx are set to the same size
-Xmn10MMaximum available value of Cenozoic 10M
-XX:+PrintGCLog printing when GC is triggered
-XX:+PrintGCDetailsLog print details when GC is triggered
–XX:UseSerialGCSerial recycling
-XX:SurvivorRatio=8eden:from:to =8:1:1
-XX:+HeapDumpOnOutOfMemoryErroGenerate Dump file during OOM
-XX:NewRatio=2Cenozoic: old age = 1:2

2.GC log analysis

2.1 first run the program and print GC parameters and logs

Setting JVM running parameters

-verbose:gc -Xms20M -Xmx20M  -Xmn10M -XX:+PrintGC -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:SurvivorRatio=8

Run program

package com.jzj.jvmtest.gctest;

/**
 * Analyze GC logs and actively trigger garbage collection through system.gc
 * Set - verbose: GC - xms20m - xmx20m - xmn10m - XX: + printgc - XX: + printgcdetails - XX: + heapdumponoutofmemoryerror - XX: survivorratio = 8
 */
public class SystemGcLog {

    private static final int ONE_MB = 1024 * 1024;

    /**
     * Set the memory of 20M, the maximum heap memory of 20M, and the new generation of 10M, then 10M is left for the old generation
     * Cenozoic 10M, Eden: survivor = 8:1, so Eden: 8M, from survivor: 1M, toSurvivor:1M, and Cenozoic available space is 8+1 9M
     *
     * @param args
     */
    public static void main(String[] args) {
        //Define 1 byte
        byte[] allocation = new byte[ONE_MB];
        //Leave allocation empty and make it garbage
        allocation = null;
        //Actively call system.gc() to count garbage and collect garbage
        System.gc();
    }
}

3. Analyze GC logs

[GC (System.gc()) [PSYoungGen: 3704K->1000K(9216K)] 3704K->1042K(19456K), 0.0010446 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (System.gc()) [PSYoungGen: 1000K->0K(9216K)] [ParOldGen: 42K->819K(10240K)] 1042K->819K(19456K), [Metaspace: 3399K->3399K(1056768K)], 0.0034435 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 246K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 3% used [0x00000000ff600000,0x00000000ff63d890,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 10240K, used 819K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  object space 10240K, 7% used [0x00000000fec00000,0x00000000fecccc28,0x00000000ff600000)
 Metaspace       used 3406K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 376K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 0
3.1 analysis of GC logs
[GC (System.gc()) [PSYoungGen: 3704K->1000K(9216K)] 3704K->1042K(19456K), 0.0010446 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC Category of] => [gc Occurrence area]
[PSYoungGen: 3704K->1000K(9216K)] => 3704K gc The capacity used in the area before the occurrence of the accident,->1000K, gc Capacity used in the area after occurrence, (9216 K)Total capacity of the current area]
Outer 3704 K->1042K(19456K) =>  3704K->1042K(19456K) 3704K gc The size used by the front heap, ->1042K gc After that, the capacity used by the heap, 19456, is the total capacity of the heap space 
[Times: user=0.00 sys=0.00, real=0.00 secs] => user:User consumption CPU Time, sys System kernel consumption CPU Time, real Clock time used from start to end
  1. GC (System.gc()) locally collects Cenozoic patterns
    Young GC: only the GC of young gen is collected. Young GC is also called "Minor GC"
    Old GC: collect only the GC of old gen. only the concurrent collection of the garbage collector CMS is in this mode
    Mixed GC: collect the GC of the whole young gen and some old gen. only garbage collector G1 has this mode

  2. Full GC is the mode of collecting all parts of the whole heap, including the Cenozoic generation, the old generation, the permanent generation (in JDK 1.8 and later, the permanent generation will be removed and replaced with Metaspace).

Different garbage collectors may trigger different conditions

  • When preparing to trigger a young GC, if the statistics say that the average size of the previous young GC is larger than the remaining space of the current old gen, the young GC will not be triggered, but the full GC will be triggered (in the GC of HotSpot VM, except the concurrent collection of the garbage collector CMS, other GC that can collect old Gen will collect the whole GC heap at the same time, including young gen, so there is no need to prepare a separate young GC in advance.)
  • If there is a perm gen, it is necessary to trigger a full GC when the perm Gen allocates space but there is not enough space
  • Execute System.gc(), heap dump with GC, which triggers full GC by default
  1. PSYoungGen/ParOldGen indicates the area where GC occurs. Our JVM uses the Server mode. The default garbage collector combination is the new generation of Parallel Scavenge garbage collector and the old generation of Parallel old garbage collector
  2. [psyounggen: 3704k - > 1000K (9216K)] = "capacity used in this area before 3704K gc occurs, - > 1000K, capacity used in this area after GC occurs, (9216K) total capacity of the current area]
  3. 3704k - > 1042k (19456k) of the outer layer = "3704k - > 1042k (19456k) the size used by the heap before 3704k GC, - > the capacity used by the heap after 1042k GC. 19456 is the total capacity of the heap space
  4. [times: user = 0.00, sys = 0.00, real = 0.00 secs] = "user: user mode consumes CPU time, sys system kernel consumes CPU time, and real clock time from start to end
3.2 analysis of GC heap log

You can see the log of the heap as follows

Heap
 PSYoungGen      total 9216K, used 246K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 3% used [0x00000000ff600000,0x00000000ff63d890,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 10240K, used 819K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  object space 10240K, 7% used [0x00000000fec00000,0x00000000fecccc28,0x00000000ff600000)
 Metaspace       used 3406K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 376K, capacity 388K, committed 512K, reserved 1048576K
  1. PSYoungGen total 9216K, used 246K. The size of the Cenozoic in the heap is 9216K in total, that is, 9m. How does 9m come From? The JVM parameter - Xmn10M and - XX:SurvivorRatio=8 indicate that Eden: From: To are 8:1:1 respectively. In this way, only one piece of From and To can be used for the Cenozoic of 10M in total, so the available memory is 8+1=9M. Now 246K is used
  2. Eden space 8192k, 8M for 3% used Eden area
  3. from space 1024K, 0% used to space 1024K, 0% From Survivor and To Survivor are both 1M
  4. ParOldGen total 10240K, used 819K. In the old age, there are 10M in total. How did 10M come from? The set - Xms20M and the maximum heap memory is 20M, of which - Xmn10M uses 10M, so there is 10M left in the old age. Used 819k and 819KB are used
  5. Metaspace used 3437K, capacity 4496K, committed 4864K, reserved 1056768K

Let's take a closer look at what Metaspace does with so many subdivisions

used and capacity are measured from the perspective of class loader
committed and reserved are measured from the perspective of operating system address space

  1. used: is the size of the part of the metachunk allocated to all class loaders to store metadata
  2. capacity: the size of the metachunk allocated to all class loaders, including the head, used, wasted, and free parts of the current metachunk of each metachunk
  3. Committed: the size of the allocated physical memory in the memory applied to the OS, including the committed part of all nodes in the VirtualSpaceList (that is, the part of non current node + current node commit), or the capacity of all class loaders + global free linked list Chunk Manager + hardware reserved HWM margin
  4. Reserved: part of the virtual address space of the JVM process, such as class metaspace. The default compressed classspacesize is 1GB, so reserved is 1GB. The metaspace in the log contains class space and no class space.
3.2 GC Metaspace meta space analysis

In JDK 1.7 and JDK 1.8, heap memory overflow occurs, and PermSize and MaxPermGen in JDK 1.8 are invalid. Therefore, it can be roughly verified that JDK 1.7 and 1.8 transfer string constants from permanent generation to heap, and there is no permanent generation in JDK 1.8.

The essence of a meta space is similar to that of a permanent generation, which is the implementation of the method area in the JVM specification. However, the biggest difference between a meta space and a permanent generation is that the meta space is not in the virtual machine, but uses local memory. Therefore, by default, the size of the meta space is limited only by local memory, but you can specify the size of the meta space through the following parameters:

-20: Metaspacesize, the initial space size. Reaching this value will trigger garbage collection for type unloading. At the same time, GC will adjust this value: if a large amount of space is released, reduce this value appropriately; if a small amount of space is released, increase this value appropriately when it does not exceed MaxMetaspaceSize.
- XX:MaxMetaspaceSize, maximum space, unlimited by default.

In addition to the above two options for specifying the size, there are two GC related attributes:
- XX:MinMetaspaceFreeRatio. After GC, the percentage of the minimum Metaspace remaining space capacity is reduced to garbage collection caused by space allocation
- XX:MaxMetaspaceFreeRatio. After GC, the percentage of the maximum Metaspace remaining space capacity is reduced to garbage collection caused by free space

Tags: Java

Posted on Sun, 21 Nov 2021 15:41:54 -0500 by greenberry