Link: mp.weixin.qq.com/s/Zl_2Ud83K… Author: Li Guo

Java Universe (Javagogo)

For sudden JVM GC problems, GC logs can help us find the root cause of the problem.

When accidents happen, they’re not usually gentle, and you can get 911 calls in the middle of the night. At this point, it’s too late to look at Jstat, we need to preserve the scene. This is the job of the watchdog, which can be configured by setting a few JVM parameters.

How do you do that?

Java 8

Let’s first look at the use in JDK8.

#! /bin/sh LOG_DIR="/tmp/logs" JAVA_OPT_LOG=" -verbose:gc" JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDetails" JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDateStamps" JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCApplicationStoppedTime" JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintTenuringDistribution" JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xloggc:${LOG_DIR}/gc_%p.log" JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log " JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}" JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"Copy the code

Synthesis of a line

-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution  -Xloggc:/tmp/logs/gc_%p.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/logs -XX:ErrorFile=/tmp/logs/hs_error_pid%p.log -XX:-OmitStackTraceInFastThrowCopy the code

And then let’s explain the parameters

  • -verbose:gc: prints GC logs

  • PrintGCDetails: Prints the detailed GC log

  • PrintGCDateStamps: system time, more readable

  • PrintGCTimeStamps: JVM start time

  • PrintGCApplicationStoppedTime: print STW time

  • By optimal MaxTenuringThreshold PrintTenuringDistribution: print object age distribution, parameters are of great help

  • Loggc: Outputs the above GC content to a file

Let’s look at the parameters and meaning of OOM

  • When HeapDumpOnOutOfMemoryError: OOM Dump information, very useful

  • HeapDumpPath: Dump file save path

  • ErrorFile: indicates the path for storing error logs

  • OmitStackTraceInFastThrow: the JVM used to reduced the log output

Open OmitStackTraceInFastThrow the parameters, if null pointer exception happened many times, you will print the following information.

java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
Copy the code

In real production, this parameter is turned on by default, which makes troubleshooting sometimes very inconvenient (many developers can’t do this). We turn it off here, but it will output all the exception stacks and log much more.

Java 13

Take a look at the use in JDK 13.

Since Java 9, more than 40 GC logging related parameters have been removed, as described in JEP 158. So this part of the logging configuration has changed a lot.

Take a look at its build script.

#! /bin/sh LOG_DIR="/tmp/logs" JAVA_OPT_LOG=" -verbose:gc" JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file=${LOG_DIR}/gc_%p.log:tags,uptime,time,level" JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:safepoint:file=${LOG_DIR}/safepoint_%p.log:tags,uptime,time,level" JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log " JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}" JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow" echo $JAVA_OPTCopy the code

Composite line display

-verbose:gc -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file
=/tmp/logs/gc_%p.log:tags,uptime,time,level -Xlog:safepoint:file=/tmp
/logs/safepoint_%p.log:tags,uptime,time,level -XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/logs -XX:ErrorFile=/tmp/logs/hs_error_pid%p.log 
-XX:-OmitStackTraceInFastThrow
Copy the code

You can see that the GC logs are printed in a completely different way, but with much cleaner log parameters than before.

In addition to GC logs, we also output safePoint logs. This log is also very important for us to analyze problems. What is SafePoint?

Safepoint is a very important concept in the JVM and refers to the point at which a thread can safely be paused.

When GC occurs, the user threads must all stop before garbage collection can take place, which is considered safe for the JVM and stable for the heap.

If a thread is slow to enter SafePoint before GC, then the entire JVM is waiting for the blocked thread, making the overall GC time longer.

So it’s not just the GC that suspends the JVM, it’s also the process into SafePoint.

As you may have noticed, Java versions have been updated very quickly in recent years, and the JVM’s configuration has actually changed a lot. In the case of GC logging, Java 9 is almost a do-over. Some articles on the Internet, write these parameters in a muddle, can not be put into production. If you encounter unrecognized parameters, check your Java version first.

Interviewer: Tell me about the parameters you used to print GC logs in your project.

You need to summarize, for example:

“I typically output verbose GC logs in my projects with readable GC log timestamps. In special cases, I will also add some logs reflecting object promotion and heap details to troubleshoot problems. In addition, the stack is automatically dumped in OOM, which I usually configure.”

Link: mp.weixin.qq.com/s/Zl_2Ud83K… Author: Li Guo

Java Universe (Javagogo)