Shulou(Shulou.com)05/31 Report--

Today, the editor will share with you the relevant knowledge points of gc log instance analysis, the content is detailed and the logic is clear. I believe most people still know too much about this knowledge, so share this article for your reference. I hope you can get something after reading this article. Let's take a look at it.

-XX:+PrintGC output brief GC log

-XX:+PrintGCDetails outputs detailed GC logs

-Xloggc:gc.log exports GC logs to a file

-XX:+PrintGCTimeStamps outputs the timestamp of the GC (in the form of a timestamp of the total time that the JVM starts to the current period)

-XX:+PrintGCDateStamps outputs the timestamp of the GC (in the form of a date, such as 2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC prints out heap information before and after GC

-verbose:gc

-XX:+PrintReferenceGC prints the number and duration of citations in the younger generation

-XX:+PrintGC and-verbose:gc

[GC (Allocation Failure) 61805K-> 9849K (256000K), 0.0041139 secs]

1. GC indicates a YGC (Young GC)

2. Allocation Failure indicates the type of failure

3. 68896K-> 5080K means that the younger generation decreases from 68896K to 5080K.

4 and 256000K represent the size of the entire heap

5. 0.0041139 secs indicates the total time spent on this GC

In JDK 8,-verbose:gc is-XX:+PrintGC, and the log format is equivalent to:-XX:+PrintGC.

However, in JDK 9-XX:+PrintGC is marked as deprecated.

-XX:+PrintGCDetails

[GC (Allocation Failure) [PSYoungGen: 53248K-> 2176K (59392K)] 58161K-> 7161K (256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]

1. GC indicates a YGC (Young GC)

2. Allocation Failure indicates the type of failure

3. PSYoungGen indicates the size of the younger generation.

4. 53248K-> 2176K means that the occupation of the younger generation is reduced from 53248K to 2176K.

5. 59392K indicates the size of the youth band.

6. 58161K-> 7161K means that the entire heap occupancy is reduced from 53248K to 2176K

7 and 256000K represent the size of the entire heap

8. 0.0039189 secs indicates the total time spent on this GC

9. [Times: user=0.02 sys=0.01, real=0.00 secs] indicates the time spent in user mode, kernel time, and real time, respectively.

Time keeps two decimal places and is rounded.

-XX:+PrintGCTimeStamps

1.963: [GC (Allocation Failure) 61805K-> 9849K (256000K), 0.0041139 secs]

If you add-XX:+PrintGCTimeStamps, the log has only one more timestamp than the one introduced in 1.963, which means that it took 1.963 seconds from JVM startup to printing GC.

-XX:+PrintGCDateStamps

2019-03-05T16:56:15.108+0800: [GC (Allocation Failure) 61805K-> 9849K (256000K), 0.0041139 secs]

If you add-XX:+PrintGCDateStamps, the log is only one more date-time than 2019-03-05T16:56:15.108+0800, indicating that the time when the GC was printed is 2019-03-05T16:56:15.108+0800. + 0800 means East 8.

-XX:+PrintHeapAtGC

Invocations represents the number of GC. Each GC is increased once, and the invocations before and after each GC is equal.

1. Heap before GC invocations=1 indicates the state of heap memory before the first GC call

2. {Heap before GC invocations=1 (full 0): indicates the heap memory condition after the first GC call

-XX:+PrintReferenceGC

This setting-XX:+PrintReferenceGC can print out the number of references to SoftReference,WeakReference,FinalReference,PhantomReference,JNI WeakReference and the length of time it takes to clean up, which can be useful when tuning YGC.

Detailed Analysis of CMS GC Log

[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K (32768K)] 36184K (62272K), 0.0018083 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

[CMS-concurrent-mark-start]

[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

[CMS-concurrent-preclean-start]

[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

[CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: user=0.57 sys=0.00, real=5.09 secs]

[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)] [Rescan (parallel), 0.0021918 secs] [weak refs processing, 0.0000245 secs] [class unloading, 0.0044098 secs] [scrub symbol table, 0.0029752 secs] [scrub string table, 0.0006820 secs] [1 CMS-remark: 19498K (32768K)] 36316K (62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

[CMS-concurrent-sweep-start]

[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

[CMS-concurrent-reset-start]

[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

33.125: [GC [DefNew: 4310K-> 872K (37888K), 0.0025925 secs] 4310K-> 880K (123904K), 0.0009434 secs]

100.667: [Full GC [Tenured: 4310K-> 872K (37888K), 0.0149142 secs] 4310K-> 880K (123904K), 0.0150007 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]

1, the preceding numbers "33.125:" and "100.667:" represent the time when the GC occurred, which means the number of seconds since the java virtual machine started.

2. The words "[GC" and "[Full GC" at the beginning of the GC log indicate the type of pauses in this garbage collection, rather than those used to distinguish between the new generation GC and the old GC. If there is a "Full", it means that Stop-The-World has occurred in this GC. If the collection triggered by calling the System.gc () method, then "[Full GC (System.gc ()") will be displayed here.

3, "[DefNew:", "[Tenured:", "[Perm:" indicate the region where GC occurs, and the region name shown here is closely related to the GC collector used; if you use the new generation in the Serial collector, it is called "Default New Generation", so it displays "[DefNew:"; if you use the ParNew collector, the name of the new generation will become "[ParNew:", meaning "Parallel New Generation" If you use the Parallel Scavenge collector, the new generation that comes with it is called "PSYoungGen".

4. "4310K-> 872K (37888K)" inside the following parentheses means "capacity used in this memory area before GC-> capacity used in this memory area after GC (total capacity of this memory area)"

"0.0025925 secs" represents the time, in seconds, taken by the GC in this area of memory.

5. "4310K-> 880K (123904K)" outside square brackets indicates "used capacity of java heap before GC"-> "used capacity of java heap after GC (total java heap capacity)"

"0.0009434 secs" represents the time, in seconds, spent by the GC in the java heap.

These are all the contents of the article "gc Log instance Analysis". Thank you for reading! I believe you will gain a lot after reading this article. The editor will update different knowledge for you every day. If you want to learn more knowledge, please pay attention to the industry information channel.

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.