There is a parameter in the JVM that prints GC logs after startup, which prints GC information in memory of the JVM running the Java program at runtime. Reading GC logs is a fundamental skill for dealing with Java virtual machine memory problems, and the log format can be different for each collector. However, the virtual machine designers maintain some commonality in the logs of each collector for the convenience of users.
We can print information by setting this parameter at startup.
-XX:+PrintGCDetails
Copy the codeHere are two classic GC logs to learn how to view GC logs:
33.125:[GC[DefNew:3324K->152K(3712K, 0.0025925secs],3324K-152K(11904K, 0.0031680secs] 100.667:[GC[DefNew:3324K->152K(3712K, 0.0025925secs] 0K-> 210K(10240K), 0.0149142 secs]4603K->210K(19456K),[Perm: 2999K->2999K(21248K)], 0.0150007 secs][Times: User =0.01 sys=0.00, real= 0.02secs]
In the first column, the first digits: “33.125:” and “100.667:” represent the time when GC occurred, which is the number of seconds since the Java virtual machine started.
Column 2: The “[GC” and “[Full GC” at the beginning of the GC log indicate the type of pauses for this garbage collection, rather than distinguishing new generation GC from old GC. If “Full” is present, stop-the-world GC occurred. If The collection was triggered by calling The system.gc () method, “[Full GC (System)” will appear here.
Column 3: The following “[DefNew”, “[Tenured”, and “[Perm” indicate the region in which GC will occur. The region names shown here are closely related to the GC collector being used. For example, in the Serial collector used in the above example, the new Generation is named “DefaultNew Generation”, so “[DefNew” is displayed. If it is a ParNew collector, the New Generation name will change to “[ParNew”, meaning “Parallel New Generation”. The Parallel Insane, the new generation to which it is derived, is called the PSYoungGen. The older generation is named the same way as the permanent generation.
The value 3324K- > 152K (3712K) in the square brackets indicates used capacity of the memory region before GC – > Used capacity of the memory region after GC (total capacity of the memory region). “3324K- > 152K (11904K)” outside square brackets means “Used capacity of the Java heap before GC – > Used capacity of the Java heap after GC (total capacity of the Java heap)”.
After that, “0.0025925 secs” indicates the amount of time, in seconds, that this memory region takes to GC. Some collectors give more specific time data, such as “[Times: User =0.01 sys=0.00, real=0.02 secs]” Respectively represents the CPU Time consumed in user mode, CPU events consumed in kernel mode, and the Wall Clock Time elapsed from the start to the end of the operation. The difference between THE CPU time and the wall clock time is that the wall clock time includes all kinds of non-computational wait time, such as waiting for disk I/O and waiting for threads to block. The CPU time does not include these wait times, but when the system has multiple cpus or cores, the multithreading operation adds up to these CPU time. So it’s perfectly normal for readers to see user or SYS time longer than real time.
I have another local example:
Code:
public class TestPretenureSizeThreshold { private static final int E_1MB=1024*1024; /** *VM parameters: -verbose: gC-xMS20m-XMx20m-xmn10m-xx: +PrintGCDetails -xx: SurvivorRatio=8 * -xx: PretenureSizeThreshold=3145728 */ public static voidtestPretenureSizeThreshold(){ byte[]allocation; // Allocate directly in old age allocation=new byte[4*E_1MB]; } public static void main(String[] args) { TestPretenureSizeThreshold.testPretenureSizeThreshold(); // System.gc(); }}Copy the code
And finally, a summary of some of the common parameters of the garbage collector, so you can try to debug different garbage collectors and see what the difference is in the format of printing?
