JDK 11 Xlog safepoint usage

Solution Verified - Updated

Environment

  • OpenJDK 11, 17

Issue

  • How to set safepoint on gc logging on JDK 11+
  • For what is worth safepoint on gc logging on JDK 11?

Resolution

JDK 11 setting example with safepoint:

JAVA_OPTS="$JAVA_OPTS -Xlog:gc*=debug,safepoint:file=/path/gc.log:time,uptime,level,tags:filecount=4,filesize=100M -XX:GCTaskTimeStampEntries=300"

Example without safepoint:

JAVA_OPTS="$JAVA_OPTS -Xlog:gc*=debug:file=/path/gc.log:time,uptime,level,tags:filecount=4,filesize=100M -XX:GCTaskTimeStampEntries=400"

With safepoint this is expected:

[2022-10-04T15:44:48.045-0400][0.997s][info ][safepoint      ] Leaving safepoint region
[2022-10-04T15:44:48.045-0400][0.997s][info ][safepoint      ] Total time for which application threads were stopped: 0.0061608 seconds, Stopping threads took: 0.0000084 seconds
[2022-10-04T15:44:48.046-0400][0.997s][info ][safepoint      ] Application time: 0.0001907 seconds
[2022-10-04T15:44:48.046-0400][0.997s][info ][safepoint      ] Entering safepoint region: RevokeBias
[2022-10-04T15:44:48.046-0400][0.997s][info ][safepoint      ] Leaving safepoint region
[2022-10-04T15:44:48.046-0400][0.997s][info ][safepoint      ] Total time for which application threads were stopped: 0.0001255 seconds, Stopping threads took: 0.0000450 seconds

Root Cause

Safepoints are points during program execution at which all GC roots are known and all heap object contents are consistent. From a global point of view, all threads must block at a safepoint before the GC can run. So the application will be suspended.
In other words, a safepoint means that all threads need to reach a certain point of execution before they are stopped. Then the VM operation is performed. After that all threads are resumed.
Also, the timestamps show the time stopped during that safepoints.

Depending on the logging level, it might be worth setting a higher GCTaskTimeStampEntries, from default 200 to 300+, as explained on GCTaskTimeStampEntries.

See solution JDK 11 Logging mechanism with -Xlog Option, about details on Xlog setting on OpenJDK 11.

Diagnostic Steps

Example:

[2022-10-20T07:32:46.287+0000][539505.672s][info ][safepoint         ] Application time: 1.0000657 seconds
[2022-10-20T07:32:46.287+0000][539505.672s][info ][safepoint         ] Entering safepoint region: Cleanup
[2022-10-20T07:32:46.287+0000][539505.672s][info ][safepoint         ] Leaving safepoint region
[2022-10-20T07:32:46.287+0000][539505.672s][info ][safepoint         ] Total time for which application threads were stopped: 0.0002361 seconds, Stopping threads took: 0.0000405 seconds
[2022-10-20T07:32:47.287+0000][539506.672s][info ][safepoint         ] Application time: 1.0000685 seconds
[2022-10-20T07:32:47.288+0000][539506.673s][info ][safepoint         ] Entering safepoint region: Cleanup
[2022-10-20T07:32:47.289+0000][539506.673s][info ][safepoint         ] Leaving safepoint region
[2022-10-20T07:32:47.289+0000][539506.673s][info ][safepoint         ] Total time for which application threads were stopped: 0.0002266 seconds, Stopping threads took: 0.0000506 seconds
SBR
Product(s)
Components
Category
Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.