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() {
+  log_gc_vtime();
+
   // 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.
@@ -1478,6 +1480,26 @@ void G1CollectedHeap::stop() {
   _cm_thread->stop();
 }
 
+class G1VCPUThreadClosure : 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 G1CollectedHeap::elapsed_gc_vtime() {
+  G1VCPUThreadClosure cl;
+  _cr->threads_do(&cl);
+  _cm->threads_do(&cl);
+  _workers->threads_do(&cl);
+  return ((double) cl.vtime() + os::thread_cpu_time(_service_thread) + os::thread_cpu_time(_cm_thread) + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC;
+}
+
+
 void G1CollectedHeap::safepoint_synchronize_begin() {
   SuspendibleThreadSet::synchronize();
 }

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

@@ -932,6 +932,8 @@ class G1CollectedHeap : public CollectedHeap {
   GrowableArray<GCMemoryManager*> memory_managers() override;
   GrowableArray<MemoryPool*> memory_pools() override;
 
+  double elapsed_gc_vtime() override;
+
   void fill_with_dummy_object(HeapWord* start, HeapWord* end, bool zap) override;
 
   static void start_codecache_marking_cycle_if_inactive(bool concurrent_mark_start);

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

@@ -160,6 +160,27 @@ void ParallelScavengeHeap::initialize_serviceability() {
 
 }
 
+void ParallelScavengeHeap::stop() {
+  log_gc_vtime();
+}
+
+class ParallelVCPUThreadClosure : 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 ParallelScavengeHeap::elapsed_gc_vtime() {
+  ParallelVCPUThreadClosure cl;
+  workers().threads_do(&cl);
+  return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC;
+}
+
 void ParallelScavengeHeap::safepoint_synchronize_begin() {
   if (UseStringDeduplication) {
     SuspendibleThreadSet::synchronize();

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

@@ -214,6 +214,9 @@ class ParallelScavengeHeap : public CollectedHeap {
   void gc_threads_do(ThreadClosure* tc) const override;
   void print_tracing_info() const override;
 
+  void stop() override;
+  double elapsed_gc_vtime() override;
+
   WorkerThreads* safepoint_workers() override { return &_workers; }
 
   PreGenGCValues get_pre_gc_values() const;

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

@@ -145,6 +145,14 @@ GrowableArray<MemoryPool*> SerialHeap::memory_pools() {
   return memory_pools;
 }
 
+void SerialHeap::stop() {
+  log_gc_vtime();
+}
+
+double SerialHeap::elapsed_gc_vtime() {
+  return (double) Universe::heap()->vm_vtime() / NANOSECS_PER_SEC;
+}
+
 void SerialHeap::safepoint_synchronize_begin() {
   if (UseStringDeduplication) {
     SuspendibleThreadSet::synchronize();

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

@@ -274,6 +274,9 @@ class SerialHeap : public CollectedHeap {
   GrowableArray<GCMemoryManager*> memory_managers() override;
   GrowableArray<MemoryPool*> memory_pools() override;
 
+  void stop() override;
+  double elapsed_gc_vtime() override;
+
   DefNewGeneration* young_gen() const {
     return _young_gen;
   }

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

@@ -66,6 +66,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> {};
 
@@ -213,6 +214,27 @@ void CollectedHeap::print() const {
   print_gc_on(tty);
 }
 
+void CollectedHeap::log_gc_vtime() {
+  if (os::is_thread_cpu_time_supported()) {
+    double process_vtime = os::elapsed_process_vtime();
+    double gc_vtime = elapsed_gc_vtime();
+
+    if (process_vtime == -1 || gc_vtime == -1) return;
+
+    log_info(gc, cpu)("Process CPU time: %fs", process_vtime);
+    log_info(gc, cpu)("GC CPU time: %fs", gc_vtime);
+    double cost = -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
+      cost = 0;
+    } else {
+      cost = 100 * gc_vtime / process_vtime;
+    }
+    log_info(gc)("GC CPU cost: %2.2f%%", cost);
+  }
+}
+
 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);

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;
@@ -246,6 +248,14 @@ class CollectedHeap : public CHeapObj<mtGC> {
   virtual void safepoint_synchronize_begin() {}
   virtual void safepoint_synchronize_end() {}
 
+  static jlong vm_vtime() {
+    return _vm_vtime;
+  }
+
+  static void add_vm_vtime(jlong time) {
+    _vm_vtime += time;
+  }
+
   void initialize_reserved_region(const ReservedHeapSpace& rs);
 
   virtual size_t capacity() const = 0;
@@ -455,6 +465,9 @@ class CollectedHeap : public CHeapObj<mtGC> {
   // Default implementation does nothing.
   virtual void print_tracing_info() const = 0;
 
+  virtual double elapsed_gc_vtime() { return -1; };
+  void log_gc_vtime();
+
   void print_before_gc() const;
   void print_after_gc() const;
 

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 operation_is_gc() const { return true; }
 };
 
 class VM_Verify : public VM_GC_Sync_Operation {

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

@@ -2202,6 +2202,7 @@ uint ShenandoahHeap::max_workers() {
 }
 
 void ShenandoahHeap::stop() {
+  log_gc_vtime();
   // 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
@@ -2219,6 +2220,23 @@ void ShenandoahHeap::stop() {
   }
 }
 
+class ShenandoahCPUThreadClosure : 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 ShenandoahHeap::elapsed_gc_vtime() {
+  ShenandoahCPUThreadClosure cl;
+  ShenandoahHeap::heap()->gc_threads_do(&cl);
+  return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC;
+}
+
 void ShenandoahHeap::stw_unload_classes(bool full_gc) {
   if (!unload_classes()) return;
   ClassUnloadingContext ctx(_workers->active_workers(),

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

@@ -209,6 +209,8 @@ class ShenandoahHeap : public CollectedHeap {
 
   void stop() override;
 
+  double elapsed_gc_vtime() override;
+
   void prepare_for_verify() override;
   void verify(VerifyOption vo) override;
 

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 operation_is_gc() const override { return true; }
 };
 
 class VM_ShenandoahReferenceOperation : public VM_ShenandoahOperation {

src/hotspot/share/gc/z/zCollectedHeap.cpp

@@ -105,11 +105,31 @@ class ZStopConcurrentGCThreadClosure : public ThreadClosure {
 
 void ZCollectedHeap::stop() {
   log_info_p(gc, exit)("Stopping ZGC");
+  log_gc_vtime();
   ZAbort::abort();
   ZStopConcurrentGCThreadClosure cl;
   gc_threads_do(&cl);
 }
 
+class ZVCPUThreadClosure : public ThreadClosure {
+private:
+  volatile jlong _vtime = 0;
+public:
+  virtual void do_thread(Thread *thread) {
+    if (thread->is_ConcurrentGC_thread() ||
+        strstr(thread->name(), "ZWorker") != nullptr) {
+      Atomic::add(&_vtime, os::thread_cpu_time(thread));
+    }
+  }
+  jlong vtime() { return _vtime; };
+};
+
+double ZCollectedHeap::elapsed_gc_vtime() {
+  ZVCPUThreadClosure cl;
+  gc_threads_do(&cl);
+  return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC;
+}
+
 size_t ZCollectedHeap::max_capacity() const {
   return _heap.max_capacity();
 }

src/hotspot/share/gc/z/zCollectedHeap.hpp

@@ -91,6 +91,8 @@ class ZCollectedHeap : public CollectedHeap {
   GrowableArray<GCMemoryManager*> memory_managers() override;
   GrowableArray<MemoryPool*> memory_pools() override;
 
+  double elapsed_gc_vtime() override;
+
   void object_iterate(ObjectClosure* cl) override;
   ParallelObjectIteratorImpl* parallel_object_iterator(uint nworkers) override;
 

src/hotspot/share/gc/z/zGeneration.cpp

@@ -442,6 +442,8 @@ class VM_ZOperation : public VM_Operation {
     OopMapCache::try_trigger_cleanup();
   }
 
+  bool operation_is_gc() const { return true; }
+
   bool success() const {
     return _success;
   }

src/hotspot/share/runtime/cpuTimeCounters.cpp

@@ -126,3 +126,7 @@ void ThreadTotalCPUTimeClosure::do_thread(Thread* thread) {
   // must ensure the thread exists and has not terminated.
   _total += os::thread_cpu_time(thread);
 }
+
+void ThreadTotalCPUTimeClosure::inc_total(jlong value) {
+  _total += value;
+}

src/hotspot/share/runtime/cpuTimeCounters.hpp

@@ -109,6 +109,7 @@ class ThreadTotalCPUTimeClosure: public ThreadClosure {
   ~ThreadTotalCPUTimeClosure();
 
   virtual void do_thread(Thread* thread);
+  void inc_total(jlong value);
 };
 
 #endif // SHARE_RUNTIME_CPUTIMECOUNTERS_HPP

src/hotspot/share/runtime/os.hpp

@@ -299,6 +299,7 @@ class os: AllStatic {
   // returns the elapsed virtual time for the current thread.
   static bool supports_vtime();
   static double elapsedVTime();
+  static double elapsed_process_vtime();
 
   // Return current local time in a string (YYYY-MM-DD HH:MM:SS).
   // It is MT safe, but not async-safe, as reading time zone

src/hotspot/share/runtime/vmOperation.hpp

@@ -168,6 +168,8 @@ class VM_Operation : public StackObj {
   // or concurrently with Java threads running.
   virtual bool evaluate_at_safepoint() const { return true; }
 
+  virtual bool operation_is_gc() const { return false; }
+
   // Debugging
   virtual void print_on_error(outputStream* st) const;
   virtual const char* name() const  { return _names[type()]; }