7166894: Add gc cause to GC logging for all collectors

Reviewed-by: mgerdin, johnc

src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp

@@ -6332,10 +6332,10 @@ void CMSCollector::reset(bool asynch) {
   )
 }
 
-void CMSCollector::do_CMS_operation(CMS_op_type op) {
+void CMSCollector::do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause) {
   gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
   TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
-  TraceTime t("GC", PrintGC, !PrintGCDetails, gclog_or_tty);
+  TraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty);
   TraceCollectorStats tcs(counters());
 
   switch (op) {

src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp

@@ -717,7 +717,7 @@ class CMSCollector: public CHeapObj {
     CMS_op_checkpointRootsFinal
   };
 
-  void do_CMS_operation(CMS_op_type op);
+  void do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause);
   bool stop_world_and_do(CMS_op_type op);
 
   OopTaskQueueSet* task_queues() { return _task_queues; }

src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp

@@ -146,7 +146,7 @@ void VM_CMS_Initial_Mark::doit() {
   VM_CMS_Operation::verify_before_gc();
 
   IsGCActiveMark x; // stop-world GC active
-  _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsInitial);
+  _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsInitial, gch->gc_cause());
 
   VM_CMS_Operation::verify_after_gc();
 #ifndef USDT2
@@ -178,7 +178,7 @@ void VM_CMS_Final_Remark::doit() {
   VM_CMS_Operation::verify_before_gc();
 
   IsGCActiveMark x; // stop-world GC active
-  _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsFinal);
+  _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsFinal, gch->gc_cause());
 
   VM_CMS_Operation::verify_after_gc();
 #ifndef USDT2

src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

@@ -1252,10 +1252,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
     gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
     TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
 
-    char verbose_str[128];
-    sprintf(verbose_str, "Full GC (%s)", GCCause::to_string(gc_cause()));
-    TraceTime t(verbose_str, G1Log::fine(), true, gclog_or_tty);
-
+    TraceTime t(GCCauseString("Full GC", gc_cause()), G1Log::fine(), true, gclog_or_tty);
     TraceCollectorStats tcs(g1mm()->full_collection_counters());
     TraceMemoryManagerStats tms(true /* fullGC */, gc_cause());
 
@@ -3600,12 +3597,10 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
     gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
     TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
 
-    char verbose_str[128];
-    sprintf(verbose_str, "GC pause (%s) (%s)%s",
-      GCCause::to_string(gc_cause()),
-      g1_policy()->gcs_are_young() ? "young" : "mixed",
-      g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : "");
-    TraceTime t(verbose_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty);
+    GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
+      .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
+      .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : "");
+    TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty);
 
     TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
     TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());

src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp

@@ -886,9 +886,8 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
                                                       size_t start_used) {
   if (G1Log::finer()) {
     gclog_or_tty->stamp(PrintGCTimeStamps);
-    gclog_or_tty->print("[GC pause (%s) (%s)",
-      GCCause::to_string(_g1->gc_cause()),
-      gcs_are_young() ? "young" : "mixed");
+    gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
+      .append(gcs_are_young() ? " (young)" : " (mixed)"));
   }
 
   // We only need to do this here as the policy will only be applied

src/share/vm/gc_implementation/parNew/parNewGeneration.cpp

@@ -916,7 +916,7 @@ void ParNewGeneration::collect(bool   full,
     size_policy->minor_collection_begin();
   }
 
-  TraceTime t1("GC", PrintGC && !PrintGCDetails, true, gclog_or_tty);
+  TraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, gclog_or_tty);
   // Capture heap used before collection (for printing).
   size_t gch_prev_used = gch->used();
 

src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp

@@ -160,16 +160,10 @@ bool PSMarkSweep::invoke_no_policy(bool clear_all_softrefs) {
 
   {
     HandleMark hm;
-    const bool is_system_gc = gc_cause == GCCause::_java_lang_system_gc;
-    // This is useful for debugging but don't change the output the
-    // the customer sees.
-    const char* gc_cause_str = "Full GC";
-    if (is_system_gc && PrintGCDetails) {
-      gc_cause_str = "Full GC (System)";
-    }
+
     gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
     TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
-    TraceTime t1(gc_cause_str, PrintGC, !PrintGCDetails, gclog_or_tty);
+    TraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty);
     TraceCollectorStats tcs(counters());
     TraceMemoryManagerStats tms(true /* Full GC */,gc_cause);
 

src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp

@@ -2047,17 +2047,9 @@ bool PSParallelCompact::invoke_no_policy(bool maximum_heap_compaction) {
     gc_task_manager()->task_idle_workers();
     heap->set_par_threads(gc_task_manager()->active_workers());
 
-    const bool is_system_gc = gc_cause == GCCause::_java_lang_system_gc;
-
-    // This is useful for debugging but don't change the output the
-    // the customer sees.
-    const char* gc_cause_str = "Full GC";
-    if (is_system_gc && PrintGCDetails) {
-      gc_cause_str = "Full GC (System)";
-    }
     gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
     TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
-    TraceTime t1(gc_cause_str, PrintGC, !PrintGCDetails, gclog_or_tty);
+    TraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty);
     TraceCollectorStats tcs(counters());
     TraceMemoryManagerStats tms(true /* Full GC */,gc_cause);
 
@@ -2090,7 +2082,8 @@ bool PSParallelCompact::invoke_no_policy(bool maximum_heap_compaction) {
     }
 #endif  // #ifndef PRODUCT
 
-    bool max_on_system_gc = UseMaximumCompactionOnSystemGC && is_system_gc;
+    bool max_on_system_gc = UseMaximumCompactionOnSystemGC
+      && gc_cause == GCCause::_java_lang_system_gc;
     summary_phase(vmthread_cm, maximum_heap_compaction || max_on_system_gc);
 
     COMPILER2_PRESENT(assert(DerivedPointerTable::is_active(), "Sanity"));

src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp

@@ -325,7 +325,7 @@ bool PSScavenge::invoke_no_policy() {
 
     gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
     TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
-    TraceTime t1("GC", PrintGC, !PrintGCDetails, gclog_or_tty);
+    TraceTime t1(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty);
     TraceCollectorStats tcs(counters());
     TraceMemoryManagerStats tms(false /* not full GC */,gc_cause);
 

src/share/vm/gc_interface/gcCause.hpp

@@ -88,4 +88,36 @@ class GCCause : public AllStatic {
   static const char* to_string(GCCause::Cause cause);
 };
 
+// Helper class for doing logging that includes the GC Cause
+// as a string.
+class GCCauseString : StackObj {
+ private:
+   static const int _length = 128;
+   char _buffer[_length];
+   int _position;
+
+ public:
+   GCCauseString(const char* prefix, GCCause::Cause cause) {
+     if (PrintGCCause) {
+      _position = jio_snprintf(_buffer, _length, "%s (%s)", prefix, GCCause::to_string(cause));
+     } else {
+      _position = jio_snprintf(_buffer, _length, "%s", prefix);
+     }
+     assert(_position >= 0 && _position <= _length,
+       err_msg("Need to increase the buffer size in GCCauseString? %d", _position));
+   }
+
+   GCCauseString& append(const char* str) {
+     int res = jio_snprintf(_buffer + _position, _length - _position, "%s", str);
+     _position += res;
+     assert(res >= 0 && _position <= _length,
+       err_msg("Need to increase the buffer size in GCCauseString? %d", res));
+     return *this;
+   }
+
+   operator const char*() {
+     return _buffer;
+   }
+};
+
 #endif // SHARE_VM_GC_INTERFACE_GCCAUSE_HPP

src/share/vm/memory/defNewGeneration.cpp

@@ -548,7 +548,7 @@ void DefNewGeneration::collect(bool   full,
 
   init_assuming_no_promotion_failure();
 
-  TraceTime t1("GC", PrintGC && !PrintGCDetails, true, gclog_or_tty);
+  TraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, gclog_or_tty);
   // Capture heap used before collection (for printing).
   size_t gch_prev_used = gch->used();
 

src/share/vm/memory/genCollectedHeap.cpp

@@ -480,26 +480,15 @@ void GenCollectedHeap::do_collection(bool  full,
   const size_t perm_prev_used = perm_gen()->used();
 
   print_heap_before_gc();
-  if (Verbose) {
-    gclog_or_tty->print_cr("GC Cause: %s", GCCause::to_string(gc_cause()));
-  }
 
   {
     FlagSetting fl(_is_gc_active, true);
 
     bool complete = full && (max_level == (n_gens()-1));
-    const char* gc_cause_str = "GC ";
-    if (complete) {
-      GCCause::Cause cause = gc_cause();
-      if (cause == GCCause::_java_lang_system_gc) {
-        gc_cause_str = "Full GC (System) ";
-      } else {
-        gc_cause_str = "Full GC ";
-      }
-    }
+    const char* gc_cause_prefix = complete ? "Full GC" : "GC";
     gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
     TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
-    TraceTime t(gc_cause_str, PrintGCDetails, false, gclog_or_tty);
+    TraceTime t(GCCauseString(gc_cause_prefix, gc_cause()), PrintGCDetails, false, gclog_or_tty);
 
     gc_prologue(complete);
     increment_total_collections(complete);

src/share/vm/memory/genMarkSweep.cpp

@@ -76,7 +76,7 @@ void GenMarkSweep::invoke_at_safepoint(int level, ReferenceProcessor* rp,
   _ref_processor = rp;
   rp->setup_policy(clear_all_softrefs);
 
-  TraceTime t1("Full GC", PrintGC && !PrintGCDetails, true, gclog_or_tty);
+  TraceTime t1(GCCauseString("Full GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, gclog_or_tty);
 
   // When collecting the permanent generation methodOops may be moving,
   // so we either have to flush all bcp data or convert it into bci.

src/share/vm/runtime/arguments.cpp

@@ -3092,6 +3092,14 @@ jint Arguments::parse(const JavaVMInitArgs* args) {
     PrintGC = true;
   }
 
+  if (!JDK_Version::is_gte_jdk18x_version()) {
+    // To avoid changing the log format for 7 updates this flag is only
+    // true by default in JDK8 and above.
+    if (FLAG_IS_DEFAULT(PrintGCCause)) {
+      FLAG_SET_DEFAULT(PrintGCCause, false);
+    }
+  }
+
   // Set object alignment values.
   set_object_alignment();
 

src/share/vm/runtime/globals.hpp

@@ -3902,7 +3902,10 @@ class CommandLineFlags {
           " of this flag is true for JDK 6 and earlier")                    \
                                                                             \
   diagnostic(bool, WhiteBoxAPI, false,                                      \
-          "Enable internal testing APIs")
+          "Enable internal testing APIs")                                   \
+                                                                            \
+  product(bool, PrintGCCause, true,                                         \
+          "Include GC cause in GC logging")
 
 /*
  *  Macros for factoring of globals

src/share/vm/runtime/java.hpp

@@ -206,6 +206,10 @@ class JDK_Version VALUE_OBJ_CLASS_SPEC {
     return current().compare_major(7) == 0;
   }
 
+  static bool is_jdk18x_version() {
+    return current().compare_major(8) == 0;
+  }
+
   static bool is_gte_jdk13x_version() {
     return current().compare_major(3) >= 0;
   }
@@ -225,6 +229,10 @@ class JDK_Version VALUE_OBJ_CLASS_SPEC {
   static bool is_gte_jdk17x_version() {
     return current().compare_major(7) >= 0;
   }
+
+  static bool is_gte_jdk18x_version() {
+    return current().compare_major(8) >= 0;
+  }
 };
 
 #endif // SHARE_VM_RUNTIME_JAVA_HPP