RFR: 8361716 : GCTraceCPUTime may report incorrect times during high load from JNI code
Jonas Norlinder
jnorlinder at openjdk.org
Mon Dec 15 14:56:22 UTC 2025
GCTraceCPUTime is used by Serial, Parallel and G1 to estimate GC CPU time spent during safepoints. It estimates CPU time by sampling the CPU time for entire process by using `os::getTimesSecs`.
This will not be correct if native code from e.g. JNI is used and is incurring a high load on the machine as native code is not paused during safepoints.
A minimal example:
public static void main(String[] args) {
// Initial GC that clean up start-up garbage etc.
System.gc();
for (int i = 1; i <= 128; i++) {
addLoad(); // Creates 128 threads, that spins in a loop
try {
Thread.sleep(2000);
} catch (InterruptedException e) {}
System.gc();
}
System.exit(0);
}
where addLoad() is a native call to a C++ program that create 128 pthreads that busy-spin forever with the largest nice value allowed.
In such scenario we can observe using G1
[0.026s][info][gc,cpu] GC(0) User=0.00s Sys=0.00s Real=0.01s
[2.103s][info][gc,cpu] GC(1) User=0.89s Sys=0.00s Real=0.03s
[4.129s][info][gc,cpu] GC(2) User=0.51s Sys=0.00s Real=0.01s
[6.195s][info][gc,cpu] GC(3) User=1.72s Sys=0.00s Real=0.06s
[8.244s][info][gc,cpu] GC(4) User=1.46s Sys=0.00s Real=0.05s
...
[201.191s][info][gc,cpu] GC(76) User=37.91s Sys=0.00s Real=1.19s
[205.064s][info][gc,cpu] GC(77) User=52.44s Sys=0.00s Real=1.64s
[208.068s][info][gc,cpu] GC(78) User=23.49s Sys=0.00s Real=0.74s
[211.795s][info][gc,cpu] GC(79) User=46.96s Sys=0.00s Real=1.47s
Since the Java code does not do anything the time should be close to 0.
# Implementation Comment
Total CPU time for GC operations on the VM thread is obtained by cumulatively adding to a counter. Since system time is calculated (on Linux) with `total - user` is value contains a small error delta. If we continuously increment a value this error would grow to an unacceptable level. Therefore, the implementation will rely on the fact that no other VM operation may run during GC safepoint, making it safe to query the VM thread for it's detailed CPU time at the start and end of GC pause.
-------------
Commit messages:
- Fix JNI bug in GCTraceCPUTime
Changes: https://git.openjdk.org/jdk/pull/28824/files
Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=28824&range=00
Issue: https://bugs.openjdk.org/browse/JDK-8361716
Stats: 203 lines in 11 files changed: 150 ins; 25 del; 28 mod
Patch: https://git.openjdk.org/jdk/pull/28824.diff
Fetch: git fetch https://git.openjdk.org/jdk.git pull/28824/head:pull/28824
PR: https://git.openjdk.org/jdk/pull/28824
More information about the hotspot-gc-dev
mailing list