JDK-8231398 : Add time tracing for gc log rotation at safepoint cleanup
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 7,8
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2019-09-24
  • Updated: 2019-11-11
  • Resolved: 2019-10-31
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
openjdk8u242 teamFixed
Related Reports
Relates :  
JDK-6941923 - RFE: Handling large log files produced by long running Java Applications
Relates :  
JDK-8145092 - Use Unified Logging for the GC logging
Description
There is a nice gotcha when dealing with low latency workloads. The safepoint cleanup does lots of things, notably rotating the GC logs in 8 (fixed by transition to Unified Logging in 9+, see JDK-8145092). Those things are normally caught by -XX:+TraceSafepointCleanupTime, but not gc log rotation, since it misses the tracing statement.

We should consider adding the tracing there.
Comments
URL: https://hg.openjdk.java.net/jdk8u/jdk8u-dev/hotspot/rev/dc471edac21e User: shade Date: 2019-10-31 18:38:04 +0000
31-10-2019
Fix Request (8u) This patch improves performance diagnostics by doing the trivial logging addition. This is a brand-new patch for 8u, RFR is here: https://mail.openjdk.java.net/pipermail/jdk8u-dev/2019-September/010341.html. Patch passes tier1 and ad-hoc experiments.
24-09-2019
RFR: https://mail.openjdk.java.net/pipermail/jdk8u-dev/2019-September/010341.html
24-09-2019
Simple patch: diff -r 7d5c800dae75 src/share/vm/runtime/safepoint.cpp --- a/src/share/vm/runtime/safepoint.cpp Tue Sep 10 19:58:22 2019 +0200 +++ b/src/share/vm/runtime/safepoint.cpp Tue Sep 24 10:05:41 2019 +0200 @@ -538,4 +538,5 @@ // rotate log files? if (UseGCLogFileRotation) { + TraceTime t8("rotating gc logs", TraceSafepointCleanupTime); gclog_or_tty->rotate_log(false); } Prints this: $ build/linux-x86_64-normal-server-fastdebug/images/j2sdk-image/bin/java -XX:+TraceSafepointCleanupTime -Xloggc:gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1K Hello 2>&1 | grep "rotating gc" 24.173: [rotating gc logs, 0.0000006 secs] 24.320: [rotating gc logs, 0.0000004 secs] 24.466: [rotating gc logs, 0.0003203 secs] # <---- additional 320 us to rotate the file 24.606: [rotating gc logs, 0.0000004 secs] 24.741: [rotating gc logs, 0.0000004 secs]
24-09-2019