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

src/hotspot/os/aix/os_aix.cpp

@@ -2464,17 +2464,19 @@ static bool thread_cpu_time_unchecked(Thread* thread, jlong* p_sys_time, jlong*
   return true;
 }
 
-jlong os::thread_cpu_time(Thread *thread, bool user_sys_cpu_time) {
+CPUTime os::detailed_thread_cpu_time(Thread* t) {
   jlong sys_time;
   jlong user_time;
 
-  if (!thread_cpu_time_unchecked(thread, &sys_time, &user_time)) {
-    return -1;
+  if (!thread_cpu_time_unchecked(t, &sys_time, &user_time)) {
+    return { -1, -1 };
   }
 
-  return user_sys_cpu_time ? sys_time + user_time : user_time;
+  return {
+    user_time,
+    sys_time
+  };
 }
-
 void os::current_thread_cpu_time_info(jvmtiTimerInfo *info_ptr) {
   info_ptr->max_value = all_bits_jlong;    // will not wrap in less than 64 bits
   info_ptr->may_skip_backward = false;     // elapsed time not wall time

src/hotspot/os/bsd/os_bsd.cpp

@@ -2290,6 +2290,29 @@ int os::open(const char *path, int oflag, int mode) {
   return fd;
 }
 
+CPUTime os::detailed_thread_cpu_time(Thread* t) {
+#ifdef __APPLE__
+  struct thread_basic_info tinfo;
+  mach_msg_type_number_t tcount = THREAD_INFO_MAX;
+  kern_return_t kr;
+  thread_t mach_thread;
+
+  mach_thread = t->osthread()->thread_id();
+  kr = thread_info(mach_thread, THREAD_BASIC_INFO, (thread_info_t)&tinfo, &tcount);
+  if (kr != KERN_SUCCESS) {
+    return { -1, -1 };
+  }
+
+  return {
+    ((jlong) tinfo.user_time.seconds * NANOSECS_PER_SEC) + ((jlong) tinfo.user_time.microseconds * MICROS_PER_SEC),
+    ((jlong) tinfo.system_time.seconds * NANOSECS_PER_SEC) + ((jlong)tinfo.system_time.microseconds * MICROS_PER_SEC)
+  };
+#else
+  Unimplemented();
+  return { 0, 0 };
+#endif
+}
+
 // current_thread_cpu_time(bool) and thread_cpu_time(Thread*, bool)
 // are used by JVM M&M and JVMTI to get user+sys or user CPU time
 // of a thread.
@@ -2324,34 +2347,6 @@ jlong os::current_thread_cpu_time(bool user_sys_cpu_time) {
 #endif
 }
 
-jlong os::thread_cpu_time(Thread *thread, bool user_sys_cpu_time) {
-#ifdef __APPLE__
-  struct thread_basic_info tinfo;
-  mach_msg_type_number_t tcount = THREAD_INFO_MAX;
-  kern_return_t kr;
-  thread_t mach_thread;
-
-  mach_thread = thread->osthread()->thread_id();
-  kr = thread_info(mach_thread, THREAD_BASIC_INFO, (thread_info_t)&tinfo, &tcount);
-  if (kr != KERN_SUCCESS) {
-    return -1;
-  }
-
-  if (user_sys_cpu_time) {
-    jlong nanos;
-    nanos = ((jlong) tinfo.system_time.seconds + tinfo.user_time.seconds) * (jlong)1000000000;
-    nanos += ((jlong) tinfo.system_time.microseconds + (jlong) tinfo.user_time.microseconds) * (jlong)1000;
-    return nanos;
-  } else {
-    return ((jlong)tinfo.user_time.seconds * 1000000000) + ((jlong)tinfo.user_time.microseconds * (jlong)1000);
-  }
-#else
-  Unimplemented();
-  return 0;
-#endif
-}
-
-
 void os::current_thread_cpu_time_info(jvmtiTimerInfo *info_ptr) {
   info_ptr->max_value = all_bits_jlong;    // will not wrap in less than 64 bits
   info_ptr->may_skip_backward = false;     // elapsed time not wall time

src/hotspot/os/linux/os_linux.cpp

@@ -4998,6 +4998,15 @@ static jlong total_thread_cpu_time(Thread *thread) {
   return success ? os::Linux::thread_cpu_time(clockid) : -1;
 }
 
+CPUTime os::detailed_thread_cpu_time(Thread* t) {
+  jlong user = user_thread_cpu_time(t);
+  jlong total = total_thread_cpu_time(t);
+  return {
+    user,
+    total - user
+  };
+}
+
 // current_thread_cpu_time(bool) and thread_cpu_time(Thread*, bool)
 // are used by JVM M&M and JVMTI to get user+sys or user CPU time
 // of a thread.
@@ -5021,14 +5030,6 @@ jlong os::current_thread_cpu_time(bool user_sys_cpu_time) {
   }
 }
 
-jlong os::thread_cpu_time(Thread *thread, bool user_sys_cpu_time) {
-  if (user_sys_cpu_time) {
-    return total_thread_cpu_time(thread);
-  } else {
-    return user_thread_cpu_time(thread);
-  }
-}
-
 static jlong user_thread_cpu_time(Thread *thread) {
   clockid_t clockid;
   bool success = get_thread_clockid(thread, &clockid, false);

src/hotspot/os/linux/os_linux.hpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 1999, 2024, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1999, 2025, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it

src/hotspot/os/windows/os_windows.cpp

@@ -52,6 +52,7 @@
 #include "runtime/mutexLocker.hpp"
 #include "runtime/objectMonitor.hpp"
 #include "runtime/orderAccess.hpp"
+#include "runtime/os.hpp"
 #include "runtime/osInfo.hpp"
 #include "runtime/osThread.hpp"
 #include "runtime/park.hpp"
@@ -4889,6 +4890,24 @@ bool os::same_files(const char* file1, const char* file2) {
 #define FT2INT64(ft) \
   ((jlong)((jlong)(ft).dwHighDateTime << 32 | (julong)(ft).dwLowDateTime))
 
+constexpr jlong filetime_interval = 100;
+
+CPUTime os::detailed_thread_cpu_time(Thread* t) {
+  FILETIME CreationTime;
+  FILETIME ExitTime;
+  FILETIME KernelTime;
+  FILETIME UserTime;
+
+  if (GetThreadTimes(t->osthread()->thread_handle(), &CreationTime,
+                      &ExitTime, &KernelTime, &UserTime) == 0) {
+    return { -1, -1 };
+  }
+
+  return {
+    FT2INT64(UserTime) * filetime_interval,
+    FT2INT64(KernelTime) * filetime_interval
+  };
+}
 
 // current_thread_cpu_time(bool) and thread_cpu_time(Thread*, bool)
 // are used by JVM M&M and JVMTI to get user+sys or user CPU time
@@ -4912,24 +4931,6 @@ jlong os::current_thread_cpu_time(bool user_sys_cpu_time) {
   return os::thread_cpu_time(Thread::current(), user_sys_cpu_time);
 }
 
-jlong os::thread_cpu_time(Thread* thread, bool user_sys_cpu_time) {
-  // This code is copy from classic VM -> hpi::sysThreadCPUTime
-  // If this function changes, os::is_thread_cpu_time_supported() should too
-  FILETIME CreationTime;
-  FILETIME ExitTime;
-  FILETIME KernelTime;
-  FILETIME UserTime;
-
-  if (GetThreadTimes(thread->osthread()->thread_handle(), &CreationTime,
-                      &ExitTime, &KernelTime, &UserTime) == 0) {
-    return -1;
-  } else if (user_sys_cpu_time) {
-    return (FT2INT64(UserTime) + FT2INT64(KernelTime)) * 100;
-  } else {
-    return FT2INT64(UserTime) * 100;
-  }
-}
-
 void os::current_thread_cpu_time_info(jvmtiTimerInfo *info_ptr) {
   info_ptr->max_value = all_bits_jlong;     // the max value -- all 64 bits
   info_ptr->may_skip_backward = false;      // GetThreadTimes returns absolute time

src/hotspot/share/gc/shared/gcTraceTime.cpp

@@ -29,6 +29,8 @@
 #include "logging/logStream.hpp"
 #include "memory/universe.hpp"
 #include "runtime/os.hpp"
+#include "services/cpuTimeUsage.hpp"
+#include "utilities/globalDefinitions.hpp"
 
 void GCTraceTimeLoggerImpl::log_start(Ticks start) {
   _start = start;
@@ -68,39 +70,48 @@ void GCTraceTimeLoggerImpl::log_end(Ticks end) {
   out.print_cr(" %.3fms", duration_in_ms);
 }
 
+static CPUTime sample_detailed_cpu_time() {
+  CPUTime cpu_time_vm = CPUTimeUsage::GC::detailed_gc_operation_vm_thread();
+  CPUTime cpu_time_gc = CPUTimeUsage::GC::detailed_gc_threads();
+  CPUTime cpu_time_stringdedup = CPUTimeUsage::GC::detailed_stringdedup();
+  return {
+    cpu_time_vm.user + cpu_time_gc.user + cpu_time_stringdedup.user,
+    cpu_time_vm.system + cpu_time_gc.system + cpu_time_stringdedup.system
+  };
+}
+
 GCTraceCPUTime::GCTraceCPUTime(GCTracer* tracer) :
   _active(log_is_enabled(Info, gc, cpu) ||
           (tracer != nullptr && tracer->should_report_cpu_time_event())),
-  _starting_user_time(0.0),
-  _starting_system_time(0.0),
+  _starting_cpu_time(0,0),
   _starting_real_time(0.0),
-  _tracer(tracer)
-{
+  _tracer(tracer) {
   if (_active) {
-    bool valid = os::getTimesSecs(&_starting_real_time,
-                                  &_starting_user_time,
-                                  &_starting_system_time);
-    if (!valid) {
-      log_warning(gc, cpu)("TraceCPUTime: os::getTimesSecs() returned invalid result");
+    _starting_cpu_time = sample_detailed_cpu_time();
+    _starting_real_time = os::elapsedTime();
+    if (CPUTimeUsage::Error::has_error()) {
+      log_warning(gc, cpu)("TraceCPUTime: CPUTimeUsage may contain invalid results");
       _active = false;
     }
   }
 }
 
 GCTraceCPUTime::~GCTraceCPUTime() {
   if (_active) {
-    double real_time, user_time, system_time;
-    bool valid = os::getTimesSecs(&real_time, &user_time, &system_time);
-    if (valid) {
-      user_time -= _starting_user_time;
-      system_time -= _starting_system_time;
+    double real_time = os::elapsedTime();
+    CPUTime cpu_time = sample_detailed_cpu_time();
+
+    if (!CPUTimeUsage::Error::has_error()) {
+      cpu_time -= _starting_cpu_time;
       real_time -= _starting_real_time;
-      log_info(gc, cpu)("User=%3.2fs Sys=%3.2fs Real=%3.2fs", user_time, system_time, real_time);
+      double user_time_seconds = 1.0 * cpu_time.user / NANOSECS_PER_SEC;
+      double system_time_seconds = 1.0 * cpu_time.system / NANOSECS_PER_SEC;
+      log_info(gc, cpu)("User=%3.2fs Sys=%3.2fs Real=%3.2fs", user_time_seconds, system_time_seconds, real_time);
       if (_tracer != nullptr) {
-        _tracer->report_cpu_time_event(user_time, system_time, real_time);
+        _tracer->report_cpu_time_event(user_time_seconds, system_time_seconds, real_time);
       }
     } else {
-      log_warning(gc, cpu)("TraceCPUTime: os::getTimesSecs() returned invalid result");
+      log_warning(gc, cpu)("TraceCPUTime: CPUTimeUsage may contain invalid results");
     }
   }
 }

src/hotspot/share/gc/shared/gcTraceTime.hpp

@@ -26,6 +26,7 @@
 #define SHARE_GC_SHARED_GCTRACETIME_HPP
 
 #include "gc/shared/gcCause.hpp"
+#include "runtime/os.hpp"
 #include "logging/log.hpp"
 #include "logging/logHandle.hpp"
 #include "logging/logStream.hpp"
@@ -35,10 +36,9 @@
 class GCTracer;
 
 class GCTraceCPUTime : public StackObj {
-  bool _active;                 // true if times will be measured and printed
-  double _starting_user_time;   // user time at start of measurement
-  double _starting_system_time; // system time at start of measurement
-  double _starting_real_time;   // real time at start of measurement
+  bool _active;                  // True if times will be measured and printed
+  CPUTime _starting_cpu_time;    // User and system time at start of measurement
+  double _starting_real_time;    // Real time at start of measurement
   GCTracer* _tracer;
 public:
   GCTraceCPUTime(GCTracer* tracer);

src/hotspot/share/runtime/os.cpp

@@ -100,6 +100,21 @@ os::PageSizes     os::_page_sizes;
 
 DEBUG_ONLY(bool os::_mutex_init_done = false;)
 
+CPUTime::CPUTime(jlong user, jlong system) :
+  user(static_cast<int64_t>(user)), system(static_cast<int64_t>(system)) {};
+
+CPUTime& CPUTime::operator+=(const CPUTime &other) {
+  user += other.user;
+  system += other.system;
+  return *this;
+}
+
+CPUTime& CPUTime::operator-=(const CPUTime &other) {
+  user -= other.user;
+  system -= other.system;
+  return *this;
+}
+
 int os::snprintf(char* buf, size_t len, const char* fmt, ...) {
   va_list args;
   va_start(args, fmt);
@@ -506,6 +521,13 @@ void os::terminate_signal_thread() {
     signal_notify(sigexitnum_pd());
 }
 
+jlong os::thread_cpu_time(Thread* thread, bool user_sys_cpu_time) {
+  CPUTime cpu_time = detailed_thread_cpu_time(thread);
+  if (cpu_time.user == -1) {
+    return -1;
+  }
+  return user_sys_cpu_time ? cpu_time.user + cpu_time.system : cpu_time.user;
+}
 
 // --------------------- loading libraries ---------------------
 

src/hotspot/share/runtime/os.hpp

@@ -167,6 +167,15 @@ class ErrnoPreserver {
   int saved_errno() { return _e; }
 };
 
+class CPUTime {
+public:
+  int64_t user;
+  int64_t system;
+  CPUTime(jlong user, jlong system);
+  CPUTime& operator+=(const CPUTime &other);
+  CPUTime& operator-=(const CPUTime &other);
+};
+
 class os: AllStatic {
   friend class JVMCIVMStructs;
   friend class MallocTracker;
@@ -994,6 +1003,8 @@ class os: AllStatic {
   static jlong current_thread_cpu_time(bool user_sys_cpu_time);
   static jlong thread_cpu_time(Thread* t, bool user_sys_cpu_time);
 
+  static CPUTime detailed_thread_cpu_time(Thread* t);
+
   // Return a bunch of info about the timers.
   // Note that the returned info for these two functions may be different
   // on some platforms