First thumb up and then watch, form a good habit

In a production environment, or any other environment where you are testing a GC problem, it is always possible to configure the parameter to print the GC log to facilitate analysis of GC-related problems.

But probably a lot of people don’t have the “perfect” configuration, either printing too little, or output to the console, or overwriting a large file, or…

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

Print the content

In order to retain as much “field evidence” as possible, it is best to print the GC-related information completely. And your program really doesn’t suffer from the same amount of performance you consume when printing log I/O during GC

Print the basic GC information

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

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

Print object distribution

In order to analyze GC promotions and the high pauses caused by promotions, how about not looking at the object age distribution log

-XX:+PrintTenuringDistribution

Examples of output content:

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

The heap data is printed after GC

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

-XX:+PrintHeapAtGC

Examples of output content:

{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
}

Print STW time

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

-XX:+PrintGCApplicationStoppedTime

Examples of output content:

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

Print SafePoint information

Before entering the STW phase, it is necessary to find a suitable SafePoint, which is also very important (not mandatory, it is best to add this parameter for debugging in case of GC problems).

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

Examples of output content:

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 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 ] 0

Print Reference processing information

If there is a problem with strong/weak/soft/virtual /finalize method, it should not be printed out.

-XX:+PrintReferenceGC

Examples of output content:

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

Complete parameter

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

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

Output way

The above just defines what is printed, and by default, these logs are printed to the console (standard output). What if your program log is also exported to the console, the log content will be messy and difficult to analyze. If you append (like Tomcat’s catalina.out append), the file gets bigger and bigger, making parsing a pain in the ass.

So we need a mechanism to split the logs, and this mechanism… The JVM is naturally provided.

Log splitting for the JVM

The JVM provides several parameters for splitting the GC log:

-xloggc :/path/to/gc.log -xloggc :/path/to/gc.log -xloggc :/path/to/gc.log -xloggc :/path/to/gc.log -XX: NumberOfGClogFiles =14 # Maximum size per file, trigger split -XX: GClogFileSize =100M

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 looks pretty good, with a few lines of configuration to get the output file out of the way. But there are some problems with this approach:

  1. The log file specified in -xloggc mode is overwritten every time it is started, and the history log will be lost
  2. When the maximum number of splits is exceeded, it will be rewritten from the 0th file, and it will be overwritten
  3. -XX: NumberOfGClogFiles cannot be set to unlimited

This overlay issue is a bit gross, the history log before each overlay is enabled… Who can stand that?

Use a timestamp to name the file

So there’s another solution. Instead of using the JVM-based split of the log, you name the log file with a timestamp each time you start, so you can use a different file each time you start, and you don’t have overwrite issues.

# use -%t for log filename -XX:+PrintGCDetails -XX:+ PrintGCDatestamps -Xloggc:/path/to/gc-%t.log # gc-2021-03-29_20-41-47.log

But is that perfect?

While there are no overwrite issues, there is no log splitting capability, so there is only one GC log file after each boot, and a single log file can be very large. Large log files are cumbersome to analyze and must be partitioned.

The combination

It only takes a little tweaking of the strategy, combining the JVM split and timestamp naming schemes, to get the optimal approach.

-xloggc :/path/to/ GC -%t.log -xloggc :/path/to/ GC -%t.log -xloggc :/path/to/ GC -%t.log -xx :+ usegclogFileRotation -XX: NumberOfGClogFiles =14 # Maximum size per file, trigger split -XX: GClogFileSize =100M

Configure the GC log file name with the timestamp, and also configure the GC log split policy for the JVM. This ensures that the GC files will not be overwritten and that the size of individual GC files will not be too large. Perfect!

The resulting log file name should look like this:

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

Best practice – full parameters

Required - XX: # + PrintGCDetails - XX: XX: + PrintGCDateStamps - + PrintTenuringDistribution - XX: XX: + PrintHeapAtGC - + PrintReferenceGC + PrintGCApplicationStoppedTime # optional - - XX: XX: XX: + PrintSafepointStatistics - PrintSafepointStatisticsCount = 1 # GC log output file path -xloggc :/path/to/gc-%t.log # -xx :+ UseGclogFileRotation # Split up to a few files, -XX: NumberOfGClogFiles =14 # Maximum size per file, trigger split -XX: GClogFileSize =100M

Original is not easy, prohibit unauthorized reprint. If my article is helpful to you, please feel free to support me at thumb up/bookmark/follow me