Analysis of GC logs in the JVM

Directory

I. FORMAT analysis of GC logs

Second, the runtime to open the GC log

I. FORMAT analysis of GC logs

Before we tell the GC log, let's run the following code

1  Packagecom.example;2 3  Public classTESTMINORGC {4     Private Static Final int_1MB = 1024*1024;5 6      Public Static voidtestallocation () {7         byte[] allocation1, Allocation2, Allocation3, Allocation4;8 9Allocation1 =New byte[2 *_1MB];TenAllocation2 =New byte[2 *_1MB]; OneAllocation3 =New byte[2 *_1MB]; AAllocation4 =New byte[4 *_1MB]; -     } -  the      Public Static voidMain () { - testallocation (); -     } -}

Configure the following virtual machine parameters to run the above program:

1 VM option:-xms20m-xmx20m-xmn10m-verbose:gc-xx:+printgcdetails-xx:survivorratio=8

Note: The-xx:+printgcdetails parameter is used to tell the virtual machine to print the memory recycle log when the garbage collection behavior occurs, and to output the current memory area allocations when the process exits.

Finally, the program outputs:

1[GC [psyounggen:7307k->480k (9216K)] 7307k->6624k (19456K), 0.0072860 secs] [times:user=0.01 sys=0.01, real=0.00secs]2[Full GC [psyounggen:480k->0k (9216K)] [paroldgen:6144k->6476k (10240K)] 6624k->6476k (19456K) [Pspermgen: 2920k->2919k (21504K)], 0.0178620 secs] [times:user=0.02 sys=0.00, real=0.02secs]3[Full GC [psyounggen:4354k->1024k (9216K)] [paroldgen:6476k->9536k (10240K)] 10831k->10560k (19456K) [ pspermgen:2921k->2921k (21504K)], 0.0139610 secs] [times:user=0.02 sys=0.00, real=0.02secs]4[Full GC [psyounggen:7339k->0k (9216K)] [paroldgen:9536k->4419k (10240K)] 16876k->4419k (19456K) [Pspermgen: 3004K->3004K (21504K)], 0.0120490 secs] [times:user=0.02 sys=0.00, real=0.01secs]5 Heap6Psyounggen total 9216K, used 4190K [0x00000007ff600000, 0x0000000800000000, 0x0000000800000000)7Eden Space 8192K, 51% used [0x00000007ff600000,0x00000007ffa17a18,0x00000007ffe00000)8From space 1024K, 0% used [0x00000007ffe00000,0x00000007ffe00000,0x00000007fff00000)9To space 1024K, 0% used [0x00000007fff00000,0x00000007fff00000,0x0000000800000000)TenParoldgen total 10240K, used 4419K [0x00000007fec00000, 0x00000007ff600000, 0x00000007ff600000) OneObject Space 10240K, 43% used [0x00000007fec00000,0x00000007ff050eb0,0x00000007ff600000) APspermgen total 21504K, used 3010K [0x00000007f9a00000, 0x00000007faf00000, 0x00000007fec00000) -Object Space 21504K, 14% used [0x00000007f9a00000,0x00000007f9cf0bf8,0x00000007faf00000)

Program output a large section of the text can not understand, these are the GC logs to be described in this article, the following is the format of the GC log:

(1) GC, full GC illustrates the type of pause for this garbage collection, rather than distinguishing between the new generation GC or the older GC. If there is "full", then this GC has "Stop-the-world".

(2) Psyounggen, Paroldgen,pspermgen represents the area where the GC occurs, and the region name shown here is closely related to the GC collector used, and the different collectors may display different names for different regions.

(3) The next "7307k->480k (9216K)" means that the memory area has used capacity (the total capacity of the memory area) after the GC has used capacity , GC .

(4)"7307k->6624k (19456K)" meansthat the Java heap has used capacity (total Java heap capacity) after GC before the Java heap has used capacity, GC.

(5)"0.0072860 secs" indicates the time taken by the GC in this memory area, in seconds.

(6)[times:user=0.01 sys=0.01, real=0.00 secs]: The user state consumes CPU time, the kernel state consumes CPU time, and the wall clock elapsed from the beginning to the end of the operation.

The difference between the ps,cpu time and the wall clock time is that the wall clock time includes various non-arithmetic waits, such as waiting for disk I/O, waiting for thread blocking, etc., while CPU time does not include these times.

Multithreaded operations overlay These CPU times when the system has multiple CPUs or multicore, so it is perfectly normal to see the user or sys time exceeding the real time.

Second, the runtime to open the GC log

We often encounter situations where the JVM is running with an error. If you can start with some startup options (startup option), you can obtain important clues related to the bug, so there is hope to cure them. But in practice, we always forget to add -XX:+HeapDumpOnOutOfMemoryError or -XX:+PrintGCDetails so necessary flag.

When faced with this dilemma, we can only close the JVM, modify the startup parameters (startup parameter), and then silently pray that the problem scenario (problematic situation) can be reproduced after the reboot. This method works occasionally, and you may be able to gather enough evidence after the scene has been reproduced to try to cure potential problems.

It is not difficult to see that the method described above is a significant problem-you have to perform an additional reboot to join the annoying debug option, not the interrupt (outage) implementation. In fact, JDK bundles provide a workable workaround that, if paid, can occasionally benefit from it.

Jinfo

Hidden in the JDK bundle is a lean gadget--jinfo. As a command-line tool, Jinfo is used to gather configuration information for a running Java process. The Jinfo attraction is the ability to -flag dynamically modify the value of certain JVM flags in a specified Java process through options. Although such flags are limited in number, they can occasionally help you. You can see which flags in the JVM can be dynamically modified by Jinfo with the following command:

My-precious me$ java-xx:+printflagsfinal-version|grep manageable intx cmsabortableprecleanwaitmillis= 100{manageable} intx cmswaitduration= 2000{manageable} bool HEAPDUMPAFTERFULLGC=false{manageable} bool HEAPDUMPBEFOREFULLGC=false{manageable} bool Heapdumponoutofmemoryerror=false{manageable} ... cut forbrevity. BOOL PRINTGC=false{manageable} bool Printgcdatestamps=false{manageable} bool Printgcdetails=false{manageable} bool Printgctimestamps=false{manageable}

-XX:+PrintFlagsFinalall of the JVM flags are listed with the option, and the flagged manageable flag is the part that deserves our attention. These flags can be dynamically modified by the JDK Management Interface (-xx:+printflagsfinal). Although it is possible to find a very similar mbean in Jconsole. But in my opinion, it's more convenient to see them in the command line way.

How to use Jinfo

Let's learn how to use jinfo through combat. In the following example, we will dynamically turn on the GC log function in a running JVM:

my-Precious me$ jps12278 highallocationrate12279 JPS12269 jconsolemy-precious Me $ jinfo-flag +printgcdetails 12278my-precious me$ jinfo-flag +printgc 12278my-precious me$

In Jinfo it is necessary to open -XX:+PrintGC and -XX:+PrintGCDetails two options to turn on the GC log, which is slightly different from the way the command-line arguments are implemented-if you set the parameters by using the startup script, it is only necessary -XX:+PrintGCDetails because -XX:+PrintGC it will be opened automatically.

However, from the results of standard output, the GC log for a process with PID 12278 can actually be displayed in a scrolling manner:

... [GC (Allocation Failure) [psyounggen:876416k->102624k (909312K)] 1094420k->320820k (1161216K), 0.2173131 secs] [times:user=0.74 sys=0.00, real=0.22 secs] ... [GC (Allocation Failure) [psyounggen:890304k->102240k (917504K)] 1108924k->320956k (1169408K), 0.2446639 secs] [times:user=0.82 sys=0.01, real=0.25 secs] ...

Similarly, if you want to turn off the GC log function, you need to execute jinfo -flag -PrintGCDetails 12278 and jinfo -flag -PrintGC 12278 command.

Analysis of GC logs in the JVM