8359110: Log accumulated GC and process CPU time upon VM exit

src/hotspot/os/posix/os_posix.cpp

@@ -76,6 +76,7 @@
 #include <sys/resource.h>
 #include <sys/socket.h>
 #include <spawn.h>
+#include <sys/resource.h>
 #include <sys/time.h>
 #include <sys/times.h>
 #include <sys/types.h>
@@ -1511,6 +1512,17 @@ jlong os::elapsed_frequency() {
 
 bool os::supports_vtime() { return true; }
 
+double os::elapsed_process_vtime() {
+  struct rusage usage;
+  int retval = getrusage(RUSAGE_SELF, &usage);
+  if (retval == 0) {
+    return usage.ru_utime.tv_sec + usage.ru_stime.tv_sec +
+         (usage.ru_utime.tv_usec + usage.ru_stime.tv_usec) / (1000.0 * 1000.0);
+  } else {
+    return -1;
+  }
+}
+
 // Return the real, user, and system times in seconds from an
 // arbitrary fixed point in the past.
 bool os::getTimesSecs(double* process_real_time,

src/hotspot/os/windows/os_windows.cpp

@@ -1209,6 +1209,39 @@ double os::elapsedVTime() {
   }
 }
 
+double os::elapsed_process_vtime() {
+  FILETIME create;
+  FILETIME exit;
+  FILETIME kernel;
+  FILETIME user;
+
+  if (GetProcessTimes(GetCurrentProcess(), &create, &exit, &kernel, &user) == 0) {
+    return -1;
+  }
+
+  SYSTEMTIME user_total;
+  if (FileTimeToSystemTime(&user, &user_total) == 0) {
+    return -1;
+  }
+
+
+  SYSTEMTIME kernel_total;
+  if (FileTimeToSystemTime(&kernel, &kernel_total) == 0) {
+    return -1;
+  }
+
+  double user_seconds =
+      double(user_total.wHour) * 3600.0 + double(user_total.wMinute) * 60.0 +
+      double(user_total.wSecond) + double(user_total.wMilliseconds) / 1000.0;
+
+  double kernel_seconds = double(kernel_total.wHour) * 3600.0 +
+                          double(kernel_total.wMinute) * 60.0 +
+                          double(kernel_total.wSecond) +
+                          double(kernel_total.wMilliseconds) / 1000.0;
+
+  return user_seconds + kernel_seconds;
+}
+
 jlong os::javaTimeMillis() {
   FILETIME wt;
   GetSystemTimeAsFileTime(&wt);

src/hotspot/share/gc/g1/g1CollectedHeap.cpp

@@ -1470,6 +1470,8 @@ bool G1CollectedHeap::concurrent_mark_is_terminating() const {
 }
 
 void G1CollectedHeap::stop() {
+  CollectedHeap::stop();
+
   // Stop all concurrent threads. We do this to make sure these threads
   // do not continue to execute and access resources (e.g. logging)
   // that are destroyed during shutdown.

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

@@ -38,6 +38,7 @@
 #include "gc/shared/gcWhen.hpp"
 #include "gc/shared/memAllocator.hpp"
 #include "gc/shared/stringdedup/stringDedup.hpp"
+#include "gc/shared/stringdedup/stringDedupProcessor.hpp"
 #include "gc/shared/tlab_globals.hpp"
 #include "logging/log.hpp"
 #include "logging/logStream.hpp"
@@ -66,6 +67,7 @@ size_t CollectedHeap::_lab_alignment_reserve = SIZE_MAX;
 Klass* CollectedHeap::_filler_object_klass = nullptr;
 size_t CollectedHeap::_filler_array_max_size = 0;
 size_t CollectedHeap::_stack_chunk_max_size = 0;
+jlong CollectedHeap::_vm_vtime = 0;
 
 class GCLogMessage : public FormatBuffer<512> {};
 
@@ -200,6 +202,23 @@ void CollectedHeap::print_relative_to_gc(GCWhen::Type when) const {
   }
 }
 
+class VCPUThreadClosure : public ThreadClosure {
+private:
+  volatile jlong _vtime = 0;
+
+public:
+  virtual void do_thread(Thread* thread) {
+    Atomic::add(&_vtime, os::thread_cpu_time(thread));
+  }
+  jlong vtime() { return _vtime; };
+};
+
+double CollectedHeap::elapsed_gc_vtime() {
+  VCPUThreadClosure cl;
+  gc_threads_do(&cl);
+  return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC;
+}
+
 void CollectedHeap::print_before_gc() const {
   print_relative_to_gc(GCWhen::BeforeGC);
 }
@@ -213,6 +232,27 @@ void CollectedHeap::print() const {
   print_gc_on(tty);
 }
 
+void CollectedHeap::log_gc_vtime() {
+  if (os::is_thread_cpu_time_supported() && log_is_enabled(Info, gc)) {
+    double process_vtime = os::elapsed_process_vtime();
+    double gc_vtime = elapsed_gc_vtime();
+    double string_dedup_vtime = UseStringDeduplication ? os::thread_cpu_time((Thread*)StringDedup::_processor->_thread) / NANOSECS_PER_SEC : 0;
+    if (process_vtime == -1 || gc_vtime == -1 || string_dedup_vtime == -1) {
+      return;
+    }
+
+    double usage = -1;
+    if (gc_vtime > process_vtime || process_vtime == 0 || gc_vtime == 0) {
+      // This can happen e.g. for short running processes with
+      // low CPU utilization
+      usage = 0;
+    } else {
+      usage = 100 * (gc_vtime + string_dedup_vtime) / process_vtime;
+    }
+    log_info(gc)("GC CPU usage: %2.2f%%", usage);
+  }
+}
+
 void CollectedHeap::trace_heap(GCWhen::Type when, const GCTracer* gc_tracer) {
   const GCHeapSummary& heap_summary = create_heap_summary();
   gc_tracer->report_gc_heap_summary(when, heap_summary);
@@ -603,6 +643,10 @@ void CollectedHeap::post_initialize() {
   initialize_serviceability();
 }
 
+void CollectedHeap::stop() {
+  log_gc_vtime();
+}
+
 #ifndef PRODUCT
 
 bool CollectedHeap::promotion_should_fail(volatile size_t* count) {

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

@@ -132,6 +132,8 @@ class CollectedHeap : public CHeapObj<mtGC> {
   NOT_PRODUCT(volatile size_t _promotion_failure_alot_count;)
   NOT_PRODUCT(volatile size_t _promotion_failure_alot_gc_number;)
 
+  static jlong _vm_vtime;
+
   // Reason for current garbage collection.  Should be set to
   // a value reflecting no collection between collections.
   GCCause::Cause _gc_cause;
@@ -240,12 +242,15 @@ class CollectedHeap : public CHeapObj<mtGC> {
   virtual void post_initialize();
 
   // Stop any onging concurrent work and prepare for exit.
-  virtual void stop() {}
+  virtual void stop();
 
   // Stop and resume concurrent GC threads interfering with safepoint operations
   virtual void safepoint_synchronize_begin() {}
   virtual void safepoint_synchronize_end() {}
 
+  static jlong vm_vtime();
+  static void add_vm_vtime(jlong time);
+
   void initialize_reserved_region(const ReservedHeapSpace& rs);
 
   virtual size_t capacity() const = 0;
@@ -455,6 +460,9 @@ class CollectedHeap : public CHeapObj<mtGC> {
   // Default implementation does nothing.
   virtual void print_tracing_info() const = 0;
 
+  virtual double elapsed_gc_vtime();
+  void log_gc_vtime();
+
   void print_before_gc() const;
   void print_after_gc() const;
 

src/hotspot/share/gc/shared/collectedHeap.inline.hpp

@@ -46,4 +46,12 @@ inline oop CollectedHeap::class_allocate(Klass* klass, size_t size, TRAPS) {
   return allocator.allocate();
 }
 
+inline jlong CollectedHeap::vm_vtime() {
+  return _vm_vtime;
+}
+
+inline void CollectedHeap::add_vm_vtime(jlong time) {
+  _vm_vtime += time;
+}
+
 #endif // SHARE_GC_SHARED_COLLECTEDHEAP_INLINE_HPP

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

@@ -93,6 +93,8 @@ class VM_GC_Sync_Operation : public VM_Operation {
   virtual bool doit_prologue();
   // Releases the Heap_lock.
   virtual void doit_epilogue();
+
+  bool is_gc_operation() const { return true; }
 };
 
 class VM_Verify : public VM_GC_Sync_Operation {

src/hotspot/share/gc/shared/stringdedup/stringDedup.hpp

@@ -100,6 +100,7 @@
 // For additional information on string deduplication, please see JEP 192,
 // https://openjdk.org/jeps/192
 
+#include "gc/shared/collectedHeap.hpp"
 #include "memory/allocation.hpp"
 #include "memory/allStatic.hpp"
 #include "oops/oopsHierarchy.hpp"
@@ -108,6 +109,7 @@
 class Klass;
 class StringDedupThread;
 class ThreadClosure;
+class CollectedHeap;
 
 // The StringDedup class provides the API for the deduplication mechanism.
 // StringDedup::Requests and the StringDedup functions for candidate testing
@@ -116,6 +118,7 @@ class ThreadClosure;
 // needed, without requiring GC-specific code.
 class StringDedup : public AllStatic {
   friend class StringDedupThread;
+  friend class CollectedHeap;
 
   class Config;
   class Processor;

src/hotspot/share/gc/shared/stringdedup/stringDedupProcessor.hpp

@@ -25,12 +25,14 @@
 #ifndef SHARE_GC_SHARED_STRINGDEDUP_STRINGDEDUPPROCESSOR_HPP
 #define SHARE_GC_SHARED_STRINGDEDUP_STRINGDEDUPPROCESSOR_HPP
 
+#include "gc/shared/collectedHeap.hpp"
 #include "gc/shared/stringdedup/stringDedup.hpp"
 #include "memory/allocation.hpp"
 #include "utilities/macros.hpp"
 
 class JavaThread;
 class OopStorage;
+class CollectedHeap;
 
 // This class performs string deduplication.  There is only one instance of
 // this class.  It processes deduplication requests.  It also manages the
@@ -42,6 +44,7 @@ class OopStorage;
 // incremental operations for resizing and for removing dead entries, so
 // safepoint checks can be performed between steps in those operations.
 class StringDedup::Processor : public CHeapObj<mtGC> {
+  friend class CollectedHeap;
   Processor();
   ~Processor() = default;
 

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

@@ -0,0 +1,42 @@
+/*
+ * Copyright (c) 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
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+#ifndef SHARE_GC_SHARED_VTIMESCOPE_HPP
+#define SHARE_GC_SHARED_VTIMESCOPE_HPP
+
+#include "memory/allocation.hpp"
+
+class VMThread;
+class VTimeScope : public StackObj {
+private:
+  jlong         _start;
+  bool          _enabled;
+  bool          _gcLogging;
+  Thread*       _thread;
+
+public:
+  VTimeScope(VMThread* thread, bool is_gc_operation);
+  ~VTimeScope();
+};
+
+#endif // SHARE_GC_SHARED_VTIMESCOPE_HPP

src/hotspot/share/gc/shared/vtimeScope.inline.hpp

@@ -0,0 +1,55 @@
+/*
+ * Copyright (c) 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
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+
+#include "gc/shared/vtimeScope.hpp"
+#include "gc/shared/collectedHeap.inline.hpp"
+#include "logging/log.hpp"
+#include "memory/universe.hpp"
+#include "runtime/vmThread.hpp"
+#include "runtime/cpuTimeCounters.hpp"
+#include "runtime/os.hpp"
+
+inline VTimeScope::VTimeScope(VMThread* thread, bool is_gc_operation)
+    : _start(0), _enabled(os::is_thread_cpu_time_supported()),
+      _gcLogging(is_gc_operation && log_is_enabled(Info, gc)),
+      _thread(thread) {
+  if (_gcLogging && _enabled) {
+    _start = os::thread_cpu_time(_thread);
+  }
+}
+
+inline VTimeScope::~VTimeScope() {
+  if (_enabled) {
+    jlong end = _gcLogging || UsePerfData ? os::thread_cpu_time(_thread) : 0;
+
+    if (_gcLogging) {
+      jlong duration = end > _start ? end - _start : 0;
+      Universe::heap()->add_vm_vtime(duration);
+    }
+
+    if (UsePerfData) {
+      CPUTimeCounters::get_instance()->update_counter(CPUTimeGroups::CPUTimeType::vm, end);
+    }
+  }
+}

src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp

@@ -2202,6 +2202,7 @@ uint ShenandoahHeap::max_workers() {
 }
 
 void ShenandoahHeap::stop() {
+  CollectedHeap::stop();
   // The shutdown sequence should be able to terminate when GC is running.
 
   // Step 0. Notify policy to disable event recording and prevent visiting gc threads during shutdown

src/hotspot/share/gc/shenandoah/shenandoahVMOperations.hpp

@@ -55,6 +55,8 @@ class VM_ShenandoahOperation : public VM_Operation {
   void log_active_generation(const char* prefix);
   bool doit_prologue() override;
   void doit_epilogue() override;
+
+  bool is_gc_operation() const override { return true; }
 };
 
 class VM_ShenandoahReferenceOperation : public VM_ShenandoahOperation {