JDK version used for this article:

Java version "1.8.0_144" Java(TM) SE Runtime Environment (build 1.8.0_144-B01) Java HotSpot(TM) 64-bit Server VM (build 25.144 - b01, mixed mode)Copy the code

1. GC log parameters

The main parameters for setting the JVM GC format log are as follows:

-xx :+PrintGC prints brief GC logs -xx :+PrintGCDetails Prints detailed GC logs -xloggc :gc.log Prints GC logs to files -xx :+PrintGCTimeStamps -xx :+PrintGCDateStamps Prints the GC timestamp (in the form of a date, For example, 2013-05-04T21:53:59.234+0800) -xx :+PrintHeapAtGC Prints heap information before and after GC -verbose: gc-xx :+PrintReferenceGC Prints the number and duration of each reference in the young generationCopy the code

This article assumes familiarity with JVM memory structures.

1.1 XX: + PrintGC and verbose: gc

If you want to enable GC log information, you can set any of the following parameters:

-XX:+PrintGC
-XX:+PrintGCDetails 
-Xloggc:gc.log 
Copy the code

If only -xx :+PrintGC is set, the log output is as follows:

[GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]
Copy the code

1. GC means a YGC (Young GC)

2. Allocation Failure indicates the type of Failure

3. 68896K->5080K indicates that the young generation decreases from 68896K to 5080K

4. 256000K indicates the size of the entire heap

5. 0.0041139 secs indicates the total time of this GC

In JDK 8, -verbose:gc is an alternate name for -xx :+PrintGC, which is equivalent to: -xx :+PrintGC.

However, in JDK 9 -xx :+PrintGC is marked as deprecated.

-verbose:gc is a standard option and -xx :+PrintGC is an experimental option. It is recommended to use -xx :gc instead of -xx :+PrintGC

Difference between -xx :+PrintGC and -verbose:gc

1.2 XX: + PrintGCDetails

[Allocation Failure (GC) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: User sys = = 0.02 0.01, real = 0.00 secs]Copy the code

1. GC means a YGC (Young GC)

2. Allocation Failure indicates the type of Failure

3. PSYoungGen indicates the size of the young generation

4. 53248K->2176K indicates that the occupation of the young generation decreases from 53248K to 2176K

5. 59392K indicates the size of the young band

6, 58161K->7161K indicates that the total heap usage decreases from 58161K to 7161K

256000K indicates the size of the entire heap

8. 0.0039189 secs indicates the total time of this GC

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

Keep two decimal places and round the time.

1.3 XX: + PrintGCTimeStamps

1.963: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]
Copy the code

If -xx :+PrintGCTimeStamps are added to the log, then there is only one more timestamp than the first one in 1.1:1.963, representing 1.963 seconds from JVM startup to printing GC.

1.4 XX: + PrintGCDateStamps

2019-03-05T16:56:15.108+0800: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]
Copy the code

If -xx :+PrintGCDateStamps is added to the log, then the log has only one more date than the first one introduced in 1.1: 2019-03-05T16:56:15.108+0800, indicating the time of printing GC is 2019-03-05T16:56:15.108+0800. +0800 means east 8.

1.5 XX: + PrintHeapAtGC

When this parameter is turned on,

Use the following parameters: -verbose: gc-xx :+ printheapatgC-xmn64m-xMS256m -xmx256m

The following logs are displayed:

{Heap before GC invocations=1 (full 0): PSYoungGen total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000) eden space 49152K, 100%, informs [x00000000fc000000 0, 0 x00000000ff000000, 0 x00000000ff000000) from space 8192 k, 0%, informs [x0000000100000000 x00000000ff800000 0, 0 x00000000ff800000, 0) to space 8192 k, 0%, informs [x00000000ff000000 0, 0 x00000000ff000000, 0 x00000000ff800000) ParOldGen total 196608 k, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000) object space 196608K, 0%, informs [x00000000f0000000 0, 0 x00000000f0000000, 0 x00000000fc000000) Metaspace informs the 7901 k, capacity 8264 k, committed 8448K, reserved 1056768K class space used 888K, capacity 986K, committed 1024K, reserved 1048576K [GC (Allocation Failure) 49152K->2416K(253952K), 0.0030218 secs] Heap after GC invocations=1 (full 0): PSYoungGen total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000) eden space 49152K, 0%, informs [x00000000fc000000 0, 0 x00000000fc000000, 0 x00000000ff000000) from space 8192 k, 29%, informs [x00000000ff800000 x00000000ff000000 0, 0 x00000000ff258020, 0) to space 8192 k, 0%, informs [x00000000ff800000 0, 0 x00000000ff800000, 0 x0000000100000000) ParOldGen total 196608 k, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000) object space 196608K, 0%, informs [x00000000f0000000 0, 0 x00000000f0004000, 0 x00000000fc000000) Metaspace informs the 7901 k, capacity 8264 k, committed 8448K, reserved 1056768K class space used 888K, capacity 986K, committed 1024K, reserved 1048576K }Copy the code

It can be seen that before and after the following log is printed

[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]
Copy the code

Detailed log information is displayed

Invocations indicates the number of GC. Each GC increases once. Invocations before and after each GC are equal

Heap before GC invocations=1 indicates the Heap memory status before the first GC call

Heap before GC invocations=1 (full 0) {Heap before GC invocations=1 (full 0); Heap before GC invocations=1 (full 0

1.6 -Xloggc:gc.log

If -xloggc is used, the following two parameters are enabled by default

-XX:+PrintGC -XX:+PrintGCTimeStamps 
Copy the code

If the startup parameters are as follows: -xloggc :gc.log -xmn64m -xMS256m -XMx256m The log format is as follows

0.318: [GC (Allocation Failure)  49152K->2384K(253952K), 0.0038675 secs]
Copy the code

Gc.log can also specify absolute paths.

The JDK version of your system and startup parameters are also printed by default at the top of gc.log

Java HotSpot(TM) 64-bit Server VM (25.144-B01) for Linux-AMd64 JRE (1.8.0_144-b01) Built on Jul 21 2017 21:57:33 by "java_re" with GCC 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 16287104k(1657700k free), swap 16636924k(15826632k free) CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:NewSize=67108864 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGCCopy the code

1.7 XX: + PrintReferenceGC

-xx :+PrintReferenceGC Print the number of SoftReference, WeakReference, FinalReference, PhantomReference, and JNI WeakReference references. And how long it takes to clean up, which can come in handy during YGC tuning.

[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000119 secs][WeakReference, 499 refs, 0.0000370 secs [FinalReference, 1045 refs, 0.0002313 secs] [JNI Weak Reference, 0.0000290 secs][PSYoungGen: [Times: user= 0.03sys =0.01, real= 0.03secs] [Times: user= 0.03sys =0.01, real= 0.03secs]Copy the code

For details, please refer to an actual combat: optimization practice of a Young GC (FinalReference).

Detailed analysis of CMS GC logs

[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs] [Times: User =0.01 sys=0.00, real=0.01 secs] [cms-concurrent-mark-start] [CMs-concurrent-mark: 0.011/0.011secs] [Times: User =0.02 sys=0.00, real=0.00 secS] [cms-concurrent-preclean-start] [CMs-concurrent-preclean: 0.001/0.00secs] [Times: User =0.00 sys=0.00, real=0.01 secs] [cms-concurrent-abortable-preclean-start] CMS: Abort preclean due to time [cmS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: User =0.57 sys=0.00, real=5.09 secs] [GC (CMS Final Remark) [YG occupancy: 1 class class consolidation][Rescan (PARALLEL), class consolidation][class consolidation] 0.0044098 secS][Scrub Symbol table, 0.0029752 secs][Scrub String table, 0.0006820 secs][1 CMS-remark: Secs] [Times: Times: User =0.02 sys=0.00, real=0.01 secs] [CMs-concurrent-sweep -start] [CMs-concurrent-sweep: 0.007/0.007 secs] [Times: User =0.01 sys=0.00, real=0.01 secs] [cms-concurrent-reset-start] [CMs-concurrent-reset: 0.000/0.000 secs] [Times: User sys = = 0.00 0.00, real = 0.00 secs]Copy the code

CMS logs are divided into two STW(Stop the World)

Init remark (1) and remark (7) phases respectively. It usually takes about 10 times longer than YGC (personal experience).

(1), [GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: User sys = = 0.01 0.00, real = 0.01 secs]

STO(Stop The World). At this time, The capacity of The old age is 32768K, and The initialization flag starts when 19498K is used. Time is short.

(2), [cms-concurrent-mark-start]

The concurrent marking phase begins

(3), [cmS-concurrent-mark: 0.011/0.011secs] [Times: user= 0.03sys =0.00, real=0.00 secs]

The concurrent marking phase takes time.

(4), [cms-concurrent-preclean-start]

The concurrent pre-cleanup phase is also executed concurrently with the user thread. The virtual machine looks for objects that are new to the old age during the concurrent marking phase (some objects may be promoted from the new generation to the old age, or some objects may be assigned to the old age). By rescanning, reduce The “relabeling” of The next phase, which stops The World.

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

The concurrent pre-cleanup phase takes time.

(6), [cms-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMs-concurrent-abortable-preclean: Secs][Times: user= 0.003 sys=0.00, real= 0.004 secs]

Concurrency can abort the pre-cleanup phase and run between parallel pre-cleanup and relabeling until the desired Eden space occupancy is achieved. This phase was added to avoid a garbage cleanup immediately after the relabeling phase

(7), [GC (CMS Final Remark) [YG occupancy: 1 class class consolidation][Rescan (PARALLEL), class consolidation][class consolidation] 0.0044098 secS][Scrub Symbol table, 0.0029752 secs][Scrub String table, 0.0006820 secs][1 CMS-remark: [Times: user= 0.03sys =0.00, real= 0.03secs] [Times: user= 0.03sys =0.00, real= 0.03secs]

STW(Stop The World), The collection phase, marks all living objects from The old age, including reference objects that were changed or newly created during The concurrent marking phase

(8), [cms-concurrent-sweep-start]

The concurrent cleanup phase begins and is executed concurrently with the user thread.

(9), [cmS-concurrent-sweep: 0.007/0.007 secs] [Times: user= 0.03sys =0.00, real= 0.03secs]

The time that the concurrent cleanup phase ends.

(10), [cms-concurrent-reset-start]

Start concurrent reset. At this stage, the data structures associated with the CMS are reinitialized so that the next cycle can proceed normally.

(11), [cmS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

The time that the concurrent reset was completed.

Reference:

Geek-yan: JVM learning notes (4) CMS GC log details

G1 garbage collector

It is recommended to use the heap with more than 6GB of memory, as recommended on the official website.

Fourth, GC tuning

The following parameters set JVM GC performance

4.1 Xmn

The recommended size is 3/8, but setting it too small, such as 1/10, will result in more Minor and Major collections.

4.2 XX: MaxTenuringThreshold = n

The value of n ranges from 0 to 15. If the value is higher than 15, JDK7 will default to 15 and JDK 8 will start with an error

5. Common problems

1. Concurrent mode failure

Occurs during a CMS GC run. For details, see:

JVM tuning – GC long pauses and solutions

GC’s pessimistic strategy

2. Promotion failed

Occurs during the Minor GC

The resources

  1. Iron anchor: Quick reading of GC logs
  2. Geek-yan: JVM learning notes (4) CMS GC log details