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

Co-authored-by: Erik Österlund <eosterlund@openjdk.org>
Co-authored-by: Jonas Norlinder <jnorlinder@openjdk.org>
Reviewed-by: tschatzl, ayang

Author: 3 people

src/hotspot/os/posix/os_posix.cpp

@@ -77,6 +77,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>
@@ -1599,6 +1600,17 @@ jlong os::elapsed_frequency() {
   return NANOSECS_PER_SEC; // nanosecond resolution
 }
 
+double os::elapsed_process_cpu_time() {
+  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

@@ -1194,6 +1194,38 @@ FILETIME java_to_windows_time(jlong l) {
   return result;
 }
 
+double os::elapsed_process_cpu_time() {
+  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/epsilon/epsilonHeap.hpp

@@ -67,6 +67,8 @@ class EpsilonHeap : public CollectedHeap {
   jint initialize() override;
   void initialize_serviceability() override;
 
+  void stop() override {};
+
   GrowableArray<GCMemoryManager*> memory_managers() override;
   GrowableArray<MemoryPool*> memory_pools() override;
 

src/hotspot/share/gc/parallel/parallelScavengeHeap.hpp

@@ -155,6 +155,8 @@ class ParallelScavengeHeap : public CollectedHeap {
   void post_initialize() override;
   void update_counters();
 
+  void stop() override {};
+
   size_t capacity() const override;
   size_t used() const override;
 

src/hotspot/share/gc/serial/serialHeap.hpp

@@ -125,6 +125,8 @@ class SerialHeap : public CollectedHeap {
   // Does operations required after initialization has been done.
   void post_initialize() override;
 
+  void stop() override {};
+
   bool is_in_reserved(const void* addr) const { return _reserved.contains(addr); }
 
   // Performance Counter support

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"
@@ -200,6 +201,34 @@ void CollectedHeap::print_relative_to_gc(GCWhen::Type when) const {
   }
 }
 
+class CPUTimeThreadClosure : public ThreadClosure {
+private:
+  jlong _cpu_time = 0;
+
+public:
+  virtual void do_thread(Thread* thread) {
+    jlong cpu_time = os::thread_cpu_time(thread);
+    if (cpu_time != -1) {
+      _cpu_time += cpu_time;
+    }
+  }
+  jlong cpu_time() { return _cpu_time; };
+};
+
+double CollectedHeap::elapsed_gc_cpu_time() const {
+  double string_dedup_cpu_time = UseStringDeduplication ?
+    os::thread_cpu_time((Thread*)StringDedup::_processor->_thread) : 0;
+
+  if (string_dedup_cpu_time == -1) {
+    string_dedup_cpu_time = 0;
+  }
+
+  CPUTimeThreadClosure cl;
+  gc_threads_do(&cl);
+
+  return (double)(cl.cpu_time() + _vmthread_cpu_time + string_dedup_cpu_time) / NANOSECS_PER_SEC;
+}
+
 void CollectedHeap::print_before_gc() const {
   print_relative_to_gc(GCWhen::BeforeGC);
 }
@@ -281,6 +310,7 @@ CollectedHeap::CollectedHeap() :
   _last_whole_heap_examined_time_ns(os::javaTimeNanos()),
   _total_collections(0),
   _total_full_collections(0),
+  _vmthread_cpu_time(0),
   _gc_cause(GCCause::_no_gc),
   _gc_lastcause(GCCause::_no_gc)
 {
@@ -603,6 +633,40 @@ void CollectedHeap::post_initialize() {
   initialize_serviceability();
 }
 
+void CollectedHeap::log_gc_cpu_time() const {
+  LogTarget(Info, gc, cpu) out;
+  if (os::is_thread_cpu_time_supported() && out.is_enabled()) {
+    double process_cpu_time = os::elapsed_process_cpu_time();
+    double gc_cpu_time = elapsed_gc_cpu_time();
+
+    if (process_cpu_time == -1 || gc_cpu_time == -1) {
+      log_warning(gc, cpu)("Could not sample CPU time");
+      return;
+    }
+
+    double usage;
+    if (gc_cpu_time > process_cpu_time ||
+        process_cpu_time == 0 || gc_cpu_time == 0) {
+      // This can happen e.g. for short running processes with
+      // low CPU utilization
+      usage = 0;
+    } else {
+      usage = 100 * gc_cpu_time / process_cpu_time;
+    }
+    out.print("GC CPU usage: %.2f%% (Process: %.4fs GC: %.4fs)", usage, process_cpu_time, gc_cpu_time);
+  }
+}
+
+void CollectedHeap::before_exit() {
+  print_tracing_info();
+
+  // Log GC CPU usage.
+  log_gc_cpu_time();
+
+  // Stop any on-going concurrent work and prepare for exit.
+  stop();
+}
+
 #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;)
 
+  jlong _vmthread_cpu_time;
+
   // Reason for current garbage collection.  Should be set to
   // a value reflecting no collection between collections.
   GCCause::Cause _gc_cause;
@@ -206,6 +208,9 @@ class CollectedHeap : public CHeapObj<mtGC> {
     return static_cast<T*>(heap);
   }
 
+  // Stop any onging concurrent work and prepare for exit.
+  virtual void stop() = 0;
+
  public:
 
   static inline size_t filler_array_max_size() {
@@ -239,13 +244,14 @@ class CollectedHeap : public CHeapObj<mtGC> {
   // This is the correct place to place such initialization methods.
   virtual void post_initialize();
 
-  // Stop any onging concurrent work and prepare for exit.
-  virtual void stop() {}
+  void before_exit();
 
   // Stop and resume concurrent GC threads interfering with safepoint operations
   virtual void safepoint_synchronize_begin() {}
   virtual void safepoint_synchronize_end() {}
 
+  void add_vmthread_cpu_time(jlong time);
+
   void initialize_reserved_region(const ReservedHeapSpace& rs);
 
   virtual size_t capacity() const = 0;
@@ -419,6 +425,8 @@ class CollectedHeap : public CHeapObj<mtGC> {
 
   void print_relative_to_gc(GCWhen::Type when) const;
 
+  void log_gc_cpu_time() const;
+
  public:
   void pre_full_gc_dump(GCTimer* timer);
   void post_full_gc_dump(GCTimer* timer);
@@ -455,6 +463,8 @@ class CollectedHeap : public CHeapObj<mtGC> {
   // Default implementation does nothing.
   virtual void print_tracing_info() const = 0;
 
+  double elapsed_gc_cpu_time() const;
+
   void print_before_gc() const;
   void print_after_gc() const;
 

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

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

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

@@ -105,6 +105,7 @@
 #include "oops/oopsHierarchy.hpp"
 #include "utilities/globalDefinitions.hpp"
 
+class CollectedHeap;
 class Klass;
 class StringDedupThread;
 class ThreadClosure;
@@ -115,6 +116,7 @@ class ThreadClosure;
 // feature.  Other functions in the StringDedup class are called where
 // needed, without requiring GC-specific code.
 class StringDedup : public AllStatic {
+  friend class CollectedHeap;
   friend class StringDedupThread;
 
   class Config;

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

@@ -29,6 +29,7 @@
 #include "memory/allocation.hpp"
 #include "utilities/macros.hpp"
 
+class CollectedHeap;
 class JavaThread;
 class OopStorage;
 
@@ -42,6 +43,8 @@ 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;