Reprinted from: mp.weixin.qq.com/s/ho1xTtyw1…

The production environment, or any other environment where GC issues are being tested, must be configured to print GC logs for GC related issues.

But maybe many people aren’t configured “perfectly,” either printing too little, printing to the console, overwriting a large file, or…

This article takes you step by step through configuring a perfect GC log printing strategy

Print the content

In order to preserve enough “field evidence”, it is best to print enough GC related information. And your program is really as good as the bit of performance you consume when you print log I/O to GC

Prints basic GC information

The first step in printing GC logs is to turn on the parameters for GC printing, which is the most basic parameter.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps
Copy the code

Print object distribution

To analyze promotions and high pauses caused by promotions at GC, how can I do without looking at the object age distribution log

-XX:+PrintTenuringDistribution
Copy the code

Example output:

Desired survivor size 59244544 bytes, new threshold 15 (max 15)
- age   1:     963176 bytes,     963176 total
- age   2:     791264 bytes,    1754440 total
- age   3:     210960 bytes,    1965400 total
- age   4:     167672 bytes,    2133072 total
- age   5:     172496 bytes,    2305568 total
- age   6:     107960 bytes,    2413528 total
- age   7:     205440 bytes,    2618968 total
- age   8:     185144 bytes,    2804112 total
- age   9:     195240 bytes,    2999352 total
- age  10:     169080 bytes,    3168432 total
- age  11:     114664 bytes,    3283096 total
- age  12:     168880 bytes,    3451976 total
- age  13:     167272 bytes,    3619248 total
- age  14:     387808 bytes,    4007056 total
- age  15:     168992 bytes,    4176048 total
Copy the code

The heap data is printed after GC

Each time a GC occurs, it is more intuitive to compare the heap memory before and after GC

-XX:+PrintHeapAtGC
Copy the code

Example output:

{Heap before GC invocations=0 (full 0):
 garbage-first heap   total 1024000K, used 324609K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 6 young (6144K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
Heap after GC invocations=1 (full 1):
 garbage-first heap   total 1024000K, used 21755K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
}
Copy the code

Print STW time

Pause times are the most important metric for GC and cannot be minimized

-XX:+PrintGCApplicationStoppedTime
Copy the code

Example output:

Total time for which application threads were stopped: 0.0254260 seconds, Stopping threads took: 0.0000218 seconds
Copy the code

Print safepoint information

It is also important to find a suitable SafePoint before entering the STW phase (optional, it is best to use this parameter when GC problems occur)

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1
Copy the code

Example output:

Vmop [threads: Total Initially_RUNNING wait_to_block] [time: spin block sync cleanup vMOP] page_trap_count 0.371: ParallelGCFailedAllocation [ 10 0 0 ] [ 0 0 0 0 7 ] 0 Execute full gc... dataList has been promoted to cms old space vmop [threads: total initially_running wait_to_block] [time: Spin block sync cleanup vMOP] page_trap_count 0.379: ParallelGCSystemGC [10 0 0] [0 0 0 0 16] 0 VMOP [Threads: Total Initially_RUNNING wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 0.396: no vm operation [ 9 1 1 ] [ 0 0 0 0 341 ] 0Copy the code

Displays Reference processing information

Strong reference/weak reference/soft reference/virtual reference/Finalize method

-XX:+PrintReferenceGC
Copy the code

Example output:

2021-02-19T12:41:30.462+ 0800:5072726.605: [SoftReference, 0 refs, 0.0000521 secs] 2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs] 2021-02-19T12:41:30.462+ 0800:5072726.605: [FinalReference, 0 refs, 0.0000056 secs] 2021-02-19T12:41:30.462+ 0800:5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs] 2021-02-19T12:41:30.462+ 0800:5072726.605: [JNI Weak Reference, 0.0000131 secs, 0.4635293 secs]Copy the code

Complete parameter

# requireds
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1
Copy the code

Output way

The above only defines what to print, and by default these logs are printed to the console (standard output). If your program logs are also exported to the console, the log content will be messy and difficult to analyze. If you append (as tomcat does with Catalina.out), the file will get bigger and bigger, making it extremely difficult to analyze.

So there needs to be a mechanism for splitting logs, and this mechanism… The JVM is naturally provided.

Log splitting for the JVM

The JVM provides several parameters for splitting GC logs:

#Path to the GC log output file
-Xloggc:/path/to/gc.log
#Enable log file splitting
-XX:+UseGCLogFileRotation 
#Split up a few files at most, then start from scratch
-XX:NumberOfGCLogFiles=14
#Each file size upper limit, exceeding the trigger split
-XX:GCLogFileSize=100M
Copy the code

According to the parameter, each GC logs as long as more than 20 m will be split up, split a maximum of 5 file, the file name followed by GC. The log. 0, GC. The 1, GC. Log. 2, the GC. The log. 3, the GC. The log. 4,…

It seems nice, but a few lines of configuration take care of the output file. But there are some problems with this approach:

  • -Xloggc specifies the log file that is overwritten. The log file is overwritten every startup and historical logs are lost
  • When the maximum number of splits is exceeded, the file is rewritten from the 0th file and overwritten
  • -xx :NumberOfGCLogFiles cannot be infinite

This overwrite problem is a bit disgusting, every time you start the history log before overwrite… Who can stand that?

Name files using timestamps

So there’s another solution. Instead of using the log splitting functionality provided by the JVM, you name the log file with a timestamp for each startup, so you can use a different file for each startup without overwriting.

#Use -%t as the log file name
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc-%t.log

#The generated file name is gC-2021-03-29_20-41-47.log
Copy the code

But is it perfect?

Although there is no overwrite problem, since there is no log splitting capability, there is only one GC log file after each startup, and the individual log file can be very large. Large log files are cumbersome to analyze and must be split.

The combination

It only takes a little tweaking here to combine the JVM split and timestamp naming schemes to get the optimal solution.

#Path to the GC log output file
-Xloggc:/path/to/gc-%t.log
#Enable log file splitting
-XX:+UseGCLogFileRotation 
#Split up a few files at most, then start from scratch
-XX:NumberOfGCLogFiles=14
#Each file size upper limit, exceeding the trigger split
-XX:GCLogFileSize=100M
Copy the code

When you configure the timestamp for the GC log file name, you also configure the JVM’s GC log splitting policy. This ensures that GC files will not be overwritten and that the size of a single GC file will not be too large. Perfect!

The resulting log file name would look something like this:

  • gc-2021-03-29_20-41-47.log.0
  • gc-2021-03-29_20-41-47.log.1
  • gc-2021-03-29_20-41-47.log.2
  • gc-2021-03-29_20-41-47.log.3
  • .

Best Practice – Complete parameters

#necessary
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

#optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

#Path to the GC log output file
-Xloggc:/path/to/gc-%t.log
#Enable log file splitting
-XX:+UseGCLogFileRotation 
#Split up a few files at most, then start writing from scratch
-XX:NumberOfGCLogFiles=14
#Each file size upper limit, exceeding the trigger split
-XX:GCLogFileSize=100M
Copy the code

Personal website

  • Github Pages
  • Gitee Pages