src/share/vm/gc/g1/concurrentMarkThread.cpp

@@ -24,16 +24,17 @@
 
 #include "precompiled.hpp"
 #include "gc/g1/concurrentMarkThread.inline.hpp"
 #include "gc/g1/g1CollectedHeap.inline.hpp"
 #include "gc/g1/g1CollectorPolicy.hpp"
-#include "gc/g1/g1Log.hpp"
 #include "gc/g1/g1MMUTracker.hpp"
 #include "gc/g1/suspendibleThreadSet.hpp"
 #include "gc/g1/vm_operations_g1.hpp"
 #include "gc/shared/gcId.hpp"
 #include "gc/shared/gcTrace.hpp"
+#include "gc/shared/gcTraceTime.hpp"
+#include "logging/log.hpp"
 #include "memory/resourceArea.hpp"
 #include "runtime/vmThread.hpp"
 
 // ======= Concurrent Mark Thread ========
 

@@ -76,24 +77,10 @@
   void do_void(){
     _cm->cleanup();
   }
 };
 
-// We want to avoid that the logging from the concurrent thread is mixed
-// with the logging from a STW GC. So, if necessary join the STS to ensure
-// that the logging is done either before or after the STW logging.
-void ConcurrentMarkThread::cm_log(bool doit, bool join_sts, const char* fmt, ...) {
-  if (doit) {
-    SuspendibleThreadSetJoiner sts_joiner(join_sts);
-    va_list args;
-    va_start(args, fmt);
-    gclog_or_tty->gclog_stamp();
-    gclog_or_tty->vprint_cr(fmt, args);
-    va_end(args);
-  }
-}
-
 // Marking pauses can be scheduled flexibly, so we might delay marking to meet MMU.
 void ConcurrentMarkThread::delay_to_keep_mmu(G1CollectorPolicy* g1_policy, bool remark) {
   if (g1_policy->adaptive_young_list_length()) {
     double now = os::elapsedTime();
     double prediction_ms = remark ? g1_policy->predict_remark_time_ms()

@@ -141,35 +128,40 @@
 
       if (!cm()->has_aborted()) {
         _cm->scanRootRegions();
       }
 
-      double mark_start_sec = os::elapsedTime();
-      cm_log(G1Log::fine(), true, "[GC concurrent-mark-start]");
+      // It would be nice to use the GCTraceConcTime class here but
+      // the "end" logging is inside the loop and not at the end of
+      // a scope. Mimicking the same log output as GCTraceConcTime instead.
+      jlong mark_start = os::elapsed_counter();
+      log_info(gc)("Concurrent Mark (%.3fs)", TimeHelper::counter_to_seconds(mark_start));
 
       int iter = 0;
       do {
         iter++;
         if (!cm()->has_aborted()) {
           _cm->markFromRoots();
         }
 
         double mark_end_time = os::elapsedVTime();
-        double mark_end_sec = os::elapsedTime();
+        jlong mark_end = os::elapsed_counter();
         _vtime_mark_accum += (mark_end_time - cycle_start);
         if (!cm()->has_aborted()) {
           delay_to_keep_mmu(g1_policy, true /* remark */);
-
-          cm_log(G1Log::fine(), true, "[GC concurrent-mark-end, %1.7lf secs]", mark_end_sec - mark_start_sec);
+          log_info(gc)("Concurrent Mark (%.3fs, %.3fs) %.3fms",
+                       TimeHelper::counter_to_seconds(mark_start),
+                       TimeHelper::counter_to_seconds(mark_end),
+                       TimeHelper::counter_to_millis(mark_end - mark_start));
 
           CMCheckpointRootsFinalClosure final_cl(_cm);
-          VM_CGC_Operation op(&final_cl, "GC remark", true /* needs_pll */);
+          VM_CGC_Operation op(&final_cl, "Pause Remark", true /* needs_pll */);
           VMThread::execute(&op);
         }
         if (cm()->restart_for_overflow()) {
-          cm_log(G1TraceMarkStackOverflow, true, "Restarting conc marking because of MS overflow in remark (restart #%d).", iter);
-          cm_log(G1Log::fine(), true, "[GC concurrent-mark-restart-for-overflow]");
+          log_debug(gc)("Restarting conc marking because of MS overflow in remark (restart #%d).", iter);
+          log_info(gc)("Concurrent Mark restart for overflow");
         }
       } while (cm()->restart_for_overflow());
 
       double end_time = os::elapsedVTime();
       // Update the total virtual time before doing this, since it will try

@@ -179,11 +171,11 @@
 
       if (!cm()->has_aborted()) {
         delay_to_keep_mmu(g1_policy, false /* cleanup */);
 
         CMCleanUp cl_cl(_cm);
-        VM_CGC_Operation op(&cl_cl, "GC cleanup", false /* needs_pll */);
+        VM_CGC_Operation op(&cl_cl, "Pause Cleanup", false /* needs_pll */);
         VMThread::execute(&op);
       } else {
         // We don't want to update the marking status if a GC pause
         // is already underway.
         SuspendibleThreadSetJoiner sts_join;

@@ -199,12 +191,11 @@
         // takes place, then we would carry on freeing regions in
         // case they are needed by the pause. If a Full GC takes
         // place, it would wait for us to process the regions
         // reclaimed by cleanup.
 
-        double cleanup_start_sec = os::elapsedTime();
-        cm_log(G1Log::fine(), false, "[GC concurrent-cleanup-start]");
+        GCTraceConcTime(Info, gc) tt("Concurrent Cleanup");
 
         // Now do the concurrent cleanup operation.
         _cm->completeCleanup();
 
         // Notify anyone who's waiting that there are no more free

@@ -215,13 +206,10 @@
         // a GC worker could be blocked waiting for the notification
         // whereas this thread will be blocked for the pause to finish
         // while it's trying to join the STS, which is conditional on
         // the GC workers finishing.
         g1h->reset_free_regions_coming();
-
-        double cleanup_end_sec = os::elapsedTime();
-        cm_log(G1Log::fine(), true, "[GC concurrent-cleanup-end, %1.7lf secs]", cleanup_end_sec - cleanup_start_sec);
       }
       guarantee(cm()->cleanup_list_is_empty(),
                 "at this point there should be no regions on the cleanup list");
 
       // There is a tricky race before recording that the concurrent

@@ -251,11 +239,11 @@
       {
         SuspendibleThreadSetJoiner sts_join;
         if (!cm()->has_aborted()) {
           g1_policy->record_concurrent_mark_cleanup_completed();
         } else {
-          cm_log(G1Log::fine(), false, "[GC concurrent-mark-abort]");
+          log_info(gc)("Concurrent Mark abort");
         }
       }
 
       // We now want to allow clearing of the marking bitmap to be
       // suspended by a collection pause.