Introduction to GC Logs

Each collector's log form is determined by their own implementation, in other words, each collector's log format can be different. However, in order to facilitate the user to read, the virtual machine designers maintain a certain commonality of the logs of each collector, such as the following two typical GC logs:

33.125:[GC [defnew:3324k->152k (3712K), 0.0025925 secs]3324k->152k (11904K), 0.0031680 secs]

100.667:[full GC [tenured: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.02 secs]

The first number "33.125:" and "100.667:" Represent the time the GC took place, meaning the number of seconds elapsed since the Java Virtual machine was started.

The "[GC" and "[Full GC" at the beginning of the GC log illustrate the type of pause for this garbage collection , not the new generation GC or the old GC.

If there is "full", the GC is Stop-the-world, for example, the following new generation collector Parnew log will also appear "[Full GC" (this is generally due to the issue of allocation guarantee failure, which is caused STW). 283.736: [Full GC [parnew:261599k->261599k (261952K), 0.0000288 secs]

If the collection triggered by the call to the System.GC () method is called, then "[Full GC (System)" is displayed here.

"[Defnew", "[tenured", "[Perm" means the area where the GC occurs , and the area name shown here is closely related to the GC collector used, such as the New generation named "Default" in the serial collector used in the example above. Generation ", so the display is" [defnew ". If it is a parnew collector, the New generation name will become "[parnew", meaning "Parallel Generation". If the parallel scavenge collector is used, it is called "Psyounggen" by the new generation, and the old and permanent generations are the same, and the name is determined by the collector.

The "3324k->152k (3712K)" Inside the square brackets means "the amount of capacity ( the total capacity of this memory area)that is used by the memory areabefore the GC has used capacity -> GC."

Outside the square brackets, "3324k->152k (11904K)" means "GC before the Java heap has used capacity ->GC After the Java heap has used capacity (total Java heap capacity )."

"0.0025925 secs" indicates the amount of time, in seconds, that the GC in this memory area occupies. Some collectors give more specific time data, such as "[times:user=0.01 sys=0.00,real=0.02 secs]", in which the user, sys, and real and the time commands of the Linux command output the same meaning, representing The CPU time consumed by the user state, CPU events consumed by the kernel state, and the wall clock time elapsed from the start to the end of the operation (Wall clock Hour). The difference between CPU time and wall clock time is that the wall clock time includes a variety of non-operational waiting times, such as waiting for disk I/O, waiting for threads to block, and CPU time does not include these times, but when the system has multiple CPUs or multicore, multi-threaded operation will overlay these CPU time, So it is perfectly normal for the reader to see the user or sys time exceeding the real time.

Introduction to GC Logs