8151614: Improve logging in concurrent mark code
Summary: 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
--- a/hotspot/src/share/vm/gc/g1/concurrentMarkThread.cpp Wed Mar 16 12:21:18 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/concurrentMarkThread.cpp Wed Mar 16 12:23:13 2016 +0100
@@ -92,15 +92,17 @@
}
}
-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 @@
}
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 @@
// correctness issue.
{
- GCConcPhaseTimer(_cm, "Concurrent Root Region Scanning");
- _cm->scanRootRegions();
+ G1ConcPhaseTimer t(_cm, "Concurrent Scan Root Regions");
+ _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");
- _cm->markFromRoots();
+ G1ConcPhaseTimer t(_cm, "Concurrent Mark From Roots");
+ _cm->mark_from_roots();
}
double mark_end_time = os::elapsedVTime();
@@ -162,18 +166,18 @@
_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",
- TimeHelper::counter_to_seconds(mark_start),
- TimeHelper::counter_to_seconds(mark_end),
- TimeHelper::counter_to_millis(mark_end - mark_start));
+ 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));
CMCheckpointRootsFinalClosure final_cl(_cm);
VM_CGC_Operation op(&final_cl, "Pause Remark", true /* needs_pll */);
VMThread::execute(&op);
}
if (cm()->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");
+ log_debug(gc, marking)("Restarting Concurrent Marking because of Mark Stack Overflow in Remark (Iteration #%d).", iter);
+ log_info(gc, marking)("Concurrent Mark Restart due to overflow");
}
} while (cm()->restart_for_overflow());
@@ -207,11 +211,9 @@
// place, it would wait for us to process the regions
// reclaimed by cleanup.
- GCTraceConcTime(Info, gc) tt("Concurrent Cleanup");
- GCConcPhaseTimer(_cm, "Concurrent Cleanup");
-
+ G1ConcPhaseTimer t(_cm, "Concurrent Complete 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 @@
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 @@
// 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");
--- a/hotspot/src/share/vm/gc/g1/g1ConcurrentMark.cpp Wed Mar 16 12:21:18 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1ConcurrentMark.cpp Wed Mar 16 12:23:13 2016 +0100
@@ -853,7 +853,7 @@
// 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 @@
}
};
-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 @@
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 @@
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 @@
g1h->trace_heap_after_concurrent_cycle();
}
-void G1ConcurrentMark::completeCleanup() {
+void G1ConcurrentMark::complete_cleanup() {
if (has_aborted()) return;
G1CollectedHeap* g1h = G1CollectedHeap::heap();
--- a/hotspot/src/share/vm/gc/g1/g1ConcurrentMark.hpp Wed Mar 16 12:21:18 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1ConcurrentMark.hpp Wed Mar 16 12:23:13 2016 +0100
@@ -608,18 +608,18 @@
// 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!
--- a/hotspot/src/share/vm/logging/logPrefix.hpp Wed Mar 16 12:21:18 2016 +0100
+++ b/hotspot/src/share/vm/logging/logPrefix.hpp Wed Mar 16 12:23:13 2016 +0100
@@ -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)) \