RFR: 8361716 : GCTraceCPUTime may report incorrect times during high load from JNI code

[Jonas Norlinder]

Hi Kirk,

That's an interesting point you bring up. While I agree that the current implementation may leak information that is useful for detecting system saturation, I'm not sure that means we can keep this implementation. The semantic contract of the [gc, cpu] log tag is to report GC CPU time. By including process wide noise we violate that contract. We will still report system and user time just more accurately so.

For diagnosing system-level distances we have JFR (jdk.CPUload) and JMX (OperatingSystemMXBean). We should probably rely on these tools rather than using GC logs to carry a noisy signal.

Best,
Jonas

On 2025-12-15, 22:51, "Kirk Pepperdine" <kirk.pepperdine at gmail.com> wrote:

Hi Jonas,

I believe the assumption of “close to 0” is based on no other processes running on that machine, not just native JNI code. In a “clean” system I have seen that these numbers are correct enough. The interesting thing about these numbers is the tell that they give you. For example, it appears as if you are running on a 32 core machine. Additionally, there are system level disturbances that are seen with an analysis of these measures. I’m sure enabling this analysis wasn’t intentional but it can be quite useful.

Kind regards,
Kirk


> On Dec 15, 2025, at 6:56 AM, Jonas Norlinder <jnorlinder at openjdk.org<mailto:jnorlinder at openjdk.org>> wrote:
>
> 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


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20251216/c860cd5e/attachment.htm>