Log GC vtime on VM exit

Author: JonasNorlinder

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 override { 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/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()]; }

src/hotspot/share/runtime/vmThread.cpp

@@ -271,14 +271,18 @@ static void post_vm_operation_event(EventExecuteVMOperation* event, VM_Operation
 
 void VMThread::evaluate_operation(VM_Operation* op) {
   ResourceMark rm;
-
+  const bool gcLogging = log_is_enabled(Info, gc) || log_is_enabled(Info, gc, cpu);
+  jlong start = 0;
   {
     PerfTraceTime vm_op_timer(perf_accumulated_vm_operation_time());
     HOTSPOT_VMOPS_BEGIN(
                      (char *) op->name(), strlen(op->name()),
                      op->evaluate_at_safepoint() ? 0 : 1);
 
     EventExecuteVMOperation event;
+    if (gcLogging && os::is_thread_cpu_time_supported()) {
+      start = os::thread_cpu_time(this);
+    }
     op->evaluate();
     if (event.should_commit()) {
       post_vm_operation_event(&event, op);
@@ -289,11 +293,18 @@ void VMThread::evaluate_operation(VM_Operation* op) {
                      op->evaluate_at_safepoint() ? 0 : 1);
   }
 
-  if (UsePerfData && os::is_thread_cpu_time_supported()) {
-    assert(Thread::current() == this, "Must be called from VM thread");
-    // Update vm_thread_cpu_time after each VM operation.
-    ThreadTotalCPUTimeClosure tttc(CPUTimeGroups::CPUTimeType::vm);
-    tttc.do_thread(this);
+  if (os::is_thread_cpu_time_supported()) {
+    jlong end = gcLogging || UsePerfData ? os::thread_cpu_time(this) : 0;
+    if (gcLogging) {
+      jlong duration = end > start ? end - start : 0;
+      Universe::heap()->add_vm_vtime(duration);
+    }
+    if (UsePerfData) {
+      assert(Thread::current() == this, "Must be called from VM thread");
+      // Update vm_thread_cpu_time after each VM operation.
+      ThreadTotalCPUTimeClosure tttc(CPUTimeGroups::CPUTimeType::vm);
+      tttc.inc_total(end);
+    }
   }
 }