8151614: Improve logging in concurrent mark code

Move detailed concurrent mark phase logging to "gc, marking" tags and add a summary "Concurrent Cycle" log message when only using "gc" logging.

Reviewed-by: sangheki, brutisso

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

@@ -92,15 +92,17 @@ void ConcurrentMarkThread::delay_to_keep_mmu(G1CollectorPolicy* g1_policy, bool
   }
 }
 
-class GCConcPhaseTimer : StackObj {
+class G1ConcPhaseTimer : public GCTraceConcTimeImpl<LogLevel::Info, LOG_TAGS(gc, marking)> {
   G1ConcurrentMark* _cm;
 
  public:
-  GCConcPhaseTimer(G1ConcurrentMark* cm, const char* title) : _cm(cm) {
+  G1ConcPhaseTimer(G1ConcurrentMark* cm, const char* title) :
+     GCTraceConcTimeImpl<LogLevel::Info,  LogTag::_gc, LogTag::_marking>(title),
+     _cm(cm) {
     _cm->register_concurrent_phase_start(title);
   }
 
-  ~GCConcPhaseTimer() {
+  ~G1ConcPhaseTimer() {
     _cm->register_concurrent_phase_end();
   }
 };
@@ -120,13 +122,15 @@ void ConcurrentMarkThread::run_service() {
     }
 
     assert(GCId::current() != GCId::undefined(), "GC id should have been set up by the initial mark GC.");
+
+    GCTraceConcTime(Info, gc) tt("Concurrent Cycle");
     {
       ResourceMark rm;
       HandleMark   hm;
       double cycle_start = os::elapsedVTime();
 
       {
-        GCConcPhaseTimer(_cm, "Concurrent Clearing of Claimed Marks");
+        G1ConcPhaseTimer t(_cm, "Concurrent Clear Claimed Marks");
         ClassLoaderDataGraph::clear_claimed_marks();
       }
 
@@ -139,22 +143,22 @@ void ConcurrentMarkThread::run_service() {
       // correctness issue.
 
       {
-        GCConcPhaseTimer(_cm, "Concurrent Root Region Scanning");
+        G1ConcPhaseTimer t(_cm, "Concurrent Scan Root Regions");
-        _cm->scanRootRegions();
+        _cm->scan_root_regions();
       }
 
       // 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));
+      log_info(gc, marking)("Concurrent Mark (%.3fs)", TimeHelper::counter_to_seconds(mark_start));
 
       int iter = 0;
       do {
         iter++;
         if (!cm()->has_aborted()) {
-          GCConcPhaseTimer(_cm, "Concurrent Mark");
+          G1ConcPhaseTimer t(_cm, "Concurrent Mark From Roots");
-          _cm->markFromRoots();
+          _cm->mark_from_roots();
         }
 
         double mark_end_time = os::elapsedVTime();
@@ -162,7 +166,7 @@ void ConcurrentMarkThread::run_service() {
         _vtime_mark_accum += (mark_end_time - cycle_start);
         if (!cm()->has_aborted()) {
           delay_to_keep_mmu(g1_policy, true /* remark */);
-          log_info(gc)("Concurrent Mark (%.3fs, %.3fs) %.3fms",
+          log_info(gc, marking)("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));
@@ -172,8 +176,8 @@ void ConcurrentMarkThread::run_service() {
           VMThread::execute(&op);
         }
         if (cm()->restart_for_overflow()) {
-          log_debug(gc)("Restarting conc marking because of MS overflow in remark (restart #%d).", iter);
+          log_debug(gc, marking)("Restarting Concurrent Marking because of Mark Stack Overflow in Remark (Iteration #%d).", iter);
-          log_info(gc)("Concurrent Mark restart for overflow");
+          log_info(gc, marking)("Concurrent Mark Restart due to overflow");
         }
       } while (cm()->restart_for_overflow());
 
@@ -207,11 +211,9 @@ void ConcurrentMarkThread::run_service() {
         // place, it would wait for us to process the regions
         // reclaimed by cleanup.
 
-        GCTraceConcTime(Info, gc) tt("Concurrent Cleanup");
+        G1ConcPhaseTimer t(_cm, "Concurrent Complete Cleanup");
-        GCConcPhaseTimer(_cm, "Concurrent Cleanup");
-
         // Now do the concurrent cleanup operation.
-        _cm->completeCleanup();
+        _cm->complete_cleanup();
 
         // Notify anyone who's waiting that there are no more free
         // regions coming. We have to do this before we join the STS
@@ -256,7 +258,7 @@ void ConcurrentMarkThread::run_service() {
         if (!cm()->has_aborted()) {
           g1_policy->record_concurrent_mark_cleanup_completed();
         } else {
-          log_info(gc)("Concurrent Mark abort");
+          log_info(gc, marking)("Concurrent Mark Abort");
         }
       }
 
@@ -265,7 +267,7 @@ void ConcurrentMarkThread::run_service() {
       // We may have aborted just before the remark. Do not bother clearing the
       // bitmap then, as it has been done during mark abort.
       if (!cm()->has_aborted()) {
-        GCConcPhaseTimer(_cm, "Concurrent Bitmap Clearing");
+        G1ConcPhaseTimer t(_cm, "Concurrent Cleanup for Next Mark");
         _cm->cleanup_for_next_mark();
       } else {
         assert(!G1VerifyBitmaps || _cm->nextMarkBitmapIsClear(), "Next mark bitmap must be clear");

hotspot/src/share/vm/gc/g1/g1ConcurrentMark.cpp

@@ -853,7 +853,7 @@ void G1ConcurrentMark::enter_first_sync_barrier(uint worker_id) {
       // marking.
       reset_marking_state(true /* clear_overflow */);
 
-      log_info(gc)("Concurrent Mark reset for overflow");
+      log_info(gc, marking)("Concurrent Mark reset for overflow");
     }
   }
 
@@ -988,13 +988,12 @@ public:
   }
 };
 
-void G1ConcurrentMark::scanRootRegions() {
+void G1ConcurrentMark::scan_root_regions() {
   // scan_in_progress() will have been set to true only if there was
   // at least one root region to scan. So, if it's false, we
   // should not attempt to do any further work.
   if (root_regions()->scan_in_progress()) {
     assert(!has_aborted(), "Aborting before root region scanning is finished not supported.");
-    GCTraceConcTime(Info, gc) tt("Concurrent Root Region Scan");
 
     _parallel_marking_threads = calc_parallel_marking_threads();
     assert(parallel_marking_threads() <= max_parallel_marking_threads(),
@@ -1052,7 +1051,7 @@ void G1ConcurrentMark::register_concurrent_gc_end_and_stop_timer() {
   register_concurrent_phase_end_common(true);
 }
 
-void G1ConcurrentMark::markFromRoots() {
+void G1ConcurrentMark::mark_from_roots() {
   // we might be tempted to assert that:
   // assert(asynch == !SafepointSynchronize::is_at_safepoint(),
   //        "inconsistent argument?");
@@ -1115,7 +1114,6 @@ void G1ConcurrentMark::checkpointRootsFinal(bool clear_all_soft_refs) {
   if (has_overflown()) {
     // Oops.  We overflowed.  Restart concurrent marking.
     _restart_for_overflow = true;
-    log_develop_trace(gc)("Remark led to restart for overflow.");
 
     // Verify the heap w.r.t. the previous marking bitmap.
     if (VerifyDuringGC) {
@@ -1761,7 +1759,7 @@ void G1ConcurrentMark::cleanup() {
   g1h->trace_heap_after_concurrent_cycle();
 }
 
-void G1ConcurrentMark::completeCleanup() {
+void G1ConcurrentMark::complete_cleanup() {
   if (has_aborted()) return;
 
   G1CollectedHeap* g1h = G1CollectedHeap::heap();

hotspot/src/share/vm/gc/g1/g1ConcurrentMark.hpp

@@ -608,18 +608,18 @@ public:
 
   // Scan all the root regions and mark everything reachable from
   // them.
-  void scanRootRegions();
+  void scan_root_regions();
 
   // Scan a single root region and mark everything reachable from it.
   void scanRootRegion(HeapRegion* hr, uint worker_id);
 
   // Do concurrent phase of marking, to a tentative transitive closure.
-  void markFromRoots();
+  void mark_from_roots();
 
   void checkpointRootsFinal(bool clear_all_soft_refs);
   void checkpointRootsFinalWork();
   void cleanup();
-  void completeCleanup();
+  void complete_cleanup();
 
   // Mark in the previous bitmap.  NB: this is usually read-only, so use
   // this carefully!

hotspot/src/share/vm/logging/logPrefix.hpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2016, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -56,6 +56,7 @@
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, freelist)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ihop)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, liveness)) \
+  LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, marking)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, metaspace)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, start)) \