Fast interpretation of GC logs (RPM)

This article is part of the Java garbage Collection manual published by Plumbr . This article describes the output format of the GC log and how to interpret the GC log to extract useful information from it. With -XX:+UseSerialGC the option, we specify that the JVM use the serial garbage collector and use the following startup parameters to let the JVM print out verbose GC logs:

-XX:+PrintGCDetails-XX:+PrintGCDateStamps-XX:+PrintGCTimeStamps

After this configuration, the log output when the GC occurs is similar to the following format (for display convenience, the line has been manually folded):

 2015-05-26t14:45:37.987-0200:151.126: [GC (Allocation Failure) 151.126: [defnew:629119k->69888k (629120K), 0.058 4157 secs] 1619346k->1273247k (2027264K), 0.0585007 secs] [times:user=0.06 sys=0.00, real=0.06 secs]2015-05-26t14:    45:59.690-0200:172.829: [GC (Allocation Failure) 172.829: [defnew:629120k->629120k (629120K), 0.0000372 secs] 172.829: [tenured:1203359k->755802k (1398144K), 0.1855567 secs] 1832479k->755802k (2027264K), [metaspace:6741 k->6741k (1056768K)], 0.1856954 secs] [times:user=0.18 sys=0.00, real=0.18 secs]  

The GC log above exposes some information from the JVM. In fact, there are 2 garbage collection events in this log fragment (garbage Collection events). One of them was to clean up the younger generation (young generation), and the second was to process the entire heap of memory. Let's look at how to interpret the first GC event, a small GC (Minor GC) that occurred in the younger generation:

2015-05-26T14:45:37.987-02001:151.1262:[GC3 (Allocation Failure4)
151.126: [DefNew5:629119K->69888K6(629120K)7
, 0.0584157 secs]1619346K->1273247K8(2027264K)9,0.0585007 secs10]
[Times: user=0.06 sys=0.00, real=0.06 secs]11

2. 2015-05-26T14:45:37.987-0200The point in time at which the –GC event (GC event) begins.
4. 151.126 the start time of the  –gc time, relative to the start time of the JVM, in seconds (measured in seconds).
6. GC  – is used to differentiate (distinguish) the flag (flag) of Minor GC or full GC. Here's  GC   indicates that the Minor GC is happening this time.
8. allocation Failure  – causes garbage collection. This GC is triggered by the fact that there are no suitable areas in the young generation to hold the data structures that need to be allocated.
10. defnew  – the name of the garbage collector used.  defnew   this name represents: Single-threaded (single-threaded), using the tag copy (mark-copy) algorithm, The Young generation garbage collector (garbage collector), which causes the entire JVM to suspend operation (Stop-the-world).
12. 629119K->69888K– Younger generations of memory usage (usage) before and after this garbage collection.
14. (629120K)– The overall size of the young generation (total size).
16. 1619346K->1273247K– The use of the entire heap memory (total used heap) before and after this garbage collection.
18. (2027264K)– Total available heap memory (totals available heap).
20. 0.0585007 secs  –GC event Duration (Duration), in seconds.
22. [times:user=0.06 sys=0.00, real=0.06 secs]  –GC event, measured by multiple classifications:  
    
    • user  – this garbage collection, all CPU time consumed by the garbage collector thread ( Total CPU time).
    • sys  – operating system calls (OS call) and the time to wait for system events (waiting for systems Event)
    • Real  – the time that the application was paused. Because the serial garbage collector (Serial garbage Collector) only uses a single thread, real time equals the sum of user and system time.

From the above analysis, we can calculate the memory usage in the JVM during garbage collection. Heap memory is used for 1.54G (1,619,346k) in total before garbage collection. Among them, the younger generation used 614M(629,119k). It can be calculated that the memory used in the old age is: 967M(990,227k).

Next set of data ( ->,   to the right) contains more important conclusions, the younger generation of memory usage after garbage collection dropped   546M (559,231k), but the total heap memory usage (all heap usage) only reduces   337M (346,099k). With this, we can calculate that there are   the young generation of 208M (213,132k) is promoted to older generation (old).

This GC event can be represented by the following, which indicates the memory usage before the GC, and below indicates the memory usage at the end of the case:

If you want to learn more, check out the complete Java garbage Collection manual, which is extracted from this example.

Original link: Understanding garbage Collection Logs

Translation Date: October 18, 2015

Translators: anchor Http://blog.csdn.net/renfufei

http://blog.csdn.net/renfufei/article/details/49230943

Fast interpretation of GC logs (RPM)