GC Log Interpretation in Java

GC log is a useful log of Java programs that best view issues when memory problems occur. Let's step through the GC log.

First, the default Java program does not turn on GC log, we can add-xx:+printgcdetails to the JVM parameters (this is only used for local debugging, not available in the build environment.

Below we can simulate a program to view the log.

public class Gclog {static final int MB = 1024x768 * 1024;static void Printgc () {byte[] b1, B2, B3, b4;b1 = new BYTE[MB];B2 = New BYTE[MB];B3 = new BYTE[MB];B4 = new BYTE[2*MB];} public static void Main (string[] args) {//TODO auto-generated method STUBPRINTGC ();}}

You can add the following startup parameters to the JVM:-xmx10m-xms10m-xmn6m-xx:+printgcdetails-xx:survivorratio=7

From the code, you can see that the JVM allocates a total of 10M of memory, of which the old pervert 4M, the young state 6M, simultaneously for the young state Eden and Survivor share 6M, the allocation of the proportion of 7:1:1, where the Eden size of 4.6m,survivor two regions respectively 0.6M

Here we default to the CMS garbage collection, below we run the program, you will see the following log

[GC [defnew:3298k->149k (5504K), 0.0053498 secs] 3298k->3221k (9600K), 0.0053750 secs] [times:user=0.00 sys=0.00, real=0.01 secs] Heap def New Generation total   5504K, used 2391K [0x33e60000, 0x34460000, 0x34460000]  Eden space 4864K,  46% use d [0x33e60000, 0x34090b28, 0x34320000) from  space 640K,  23% used [0x343c0000, 0x343e5418, 0x34460000]  to   space 640K,   0% used [0x34320000, 0x34320000, 0x343c0000) tenured generation total   4096K, used 3072K [0x34460 0x34860000, 0x34860000) The   space 4096K,  75% used [0x34460000, 0x34760030, 0x34760200, 0x34860000)  Compacting Perm Gen Total  12288K, used 376K [0x34860000, 0x35460000, 0x38860000) The   space 12288K,   3% used [0x34860000, 0x348be298, 0x348be400, 0x35460000]    Ro Space 10240K,  55% used [0x38860000, 0x38de3320, 0x38de3400, 0x39260000)    rw space 12288K,  55% used [0x39 260000, 0x39906128, 0x39906200, 0x39e60000)

Below you can analyze the log from the point of view of the program.

1M-->1M--->1m--->2m memory is applied sequentially in the program

When applying for 1M for the first time, the new eco-space is enough to be put directly into

When the second application for 1M, the new ecological space is still enough, directly into

When the third application for 1M, the new ecological space is still enough, directly into

When the fourth time to apply for 1M, the new ecological space is insufficient to start GC, and at this time there are 3 1M objects, and the survivor region is dissatisfied with 1M, so directly into the old age state, which is the original 3 1M objects into the old state, 2M objects into Eden

Take a look at this line:

Defnew says new ecology: 3298k->149k (5504K), 0.0053498 secs

Indicates that the new ecology has been recycled from 3298K to 149K, that is, the previous 3M was recycled, and 5504K represents the total memory size of the area.

3298k->3221k (9600K), 0.0053750 secs] represents the size of the entire JVM heap because there is no recoverable object, so the total size of the nature has not changed, 9600K is the total heap size of Java 9600K. (Although allocated 10M, there are other memory areas such as persistent state)

[times:user=0.00 sys=0.00, real=0.01 secs] represents the system resources spent by GC

-------------------------------------------------------------------------------Ornate Split Line------------------------------------- --------------------------------------------------------------------

Take a look at this pile of detailed information.

Heap
def New Generation Total 5504K, used 2391K [0x33e60000, 0x34460000, 0x34460000)-------------> New Ecological Size, total,used
Eden Space 4864K, 46% used [0x33e60000, 0x34090b28, 0x34320000)
From space 640K, 23% used [0x343c0000, 0x343e5418, 0x34460000)-------------> In this case, because the area is very small and cannot be placed into the object, it is not actually used.
To space 640K, 0% used [0x34320000, 0x34320000, 0x343c0000)
Tenured generation total 4096K, used 3072K [0x34460000, 0x34860000, 0x34860000)-------------> Old age
The space 4096K, 75% used [0x34460000, 0x34760030, 0x34760200, 0x34860000)
Compacting Perm Gen Total 12288K, used 376K [0x34860000, 0x35460000, 0x38860000)-------------> Because of the old state of 4M, has been put into 3 m, So the compression is turned on.
The space 12288K, 3% used [0x34860000, 0x348be298, 0x348be400, 0x35460000)
Ro space 10240K, 55% used [0x38860000, 0x38de3320, 0x38de3400, 0x39260000)
RW Space 12288K, 55% used [0x39260000, 0x39906128, 0x39906200, 0x39e60000)

For Java programs in the build environment can be added to generate GC log, easy to troubleshoot when problems occur

-verbose:gc-xloggc:/usr/gclog-xx:+printgcdetails Xx:+printgctimestamps

For the time being, the JVM memory model does not say much here, and I will write some of the tools that the JVM optimizes to debug online systems on-line.

GC Log Interpretation in Java