--- old/src/share/vm/gc/g1/concurrentMarkThread.cpp 2015-06-23 11:13:44.275875979 +0200 +++ new/src/share/vm/gc/g1/concurrentMarkThread.cpp 2015-06-23 11:13:44.155875984 +0200 @@ -79,11 +79,11 @@ }; // We want to avoid that the logging from the concurrent thread is mixed -// with the logging from a STW GC. Join the STS to ensure that the logging -// is done either before or after the STW logging. -void ConcurrentMarkThread::cm_log(bool doit, const char* fmt, ...) { +// 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; + SuspendibleThreadSetJoiner sts_joiner(join_sts); va_list args; va_start(args, fmt); gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); @@ -121,28 +121,18 @@ // subsequent GC could block us from joining the STS and proceed // without the root regions have been scanned which would be a // correctness issue. - // This means that we can not use the cm_log() method for the logging - // regarding the root region scanning below. double scan_start = os::elapsedTime(); if (!cm()->has_aborted()) { - if (G1Log::fine()) { - gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); - gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]"); - } + cm_log(G1Log::fine(), false, "[GC concurrent-root-region-scan-start]"); _cm->scanRootRegions(); - double scan_end = os::elapsedTime(); - if (G1Log::fine()) { - gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); - gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf secs]", - scan_end - scan_start); - } + cm_log(G1Log::fine(), false, "[GC concurrent-root-region-scan-end, %1.7lf secs]", os::elapsedTime() - scan_start); } double mark_start_sec = os::elapsedTime(); - cm_log(G1Log::fine(), "[GC concurrent-mark-start]"); + cm_log(G1Log::fine(), true, "[GC concurrent-mark-start]"); int iter = 0; do { @@ -162,15 +152,15 @@ os::sleep(current_thread, sleep_time_ms, false); } - cm_log(G1Log::fine(), "[GC concurrent-mark-end, %1.7lf secs]", mark_end_sec - mark_start_sec); + cm_log(G1Log::fine(), true, "[GC concurrent-mark-end, %1.7lf secs]", mark_end_sec - mark_start_sec); CMCheckpointRootsFinalClosure final_cl(_cm); VM_CGC_Operation op(&final_cl, "GC remark", true /* needs_pll */); VMThread::execute(&op); } if (cm()->restart_for_overflow()) { - cm_log(G1TraceMarkStackOverflow, "Restarting conc marking because of MS overflow in remark (restart #%d).", iter); - cm_log(G1Log::fine(), "[GC concurrent-mark-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]"); } } while (cm()->restart_for_overflow()); @@ -210,7 +200,7 @@ // reclaimed by cleanup. double cleanup_start_sec = os::elapsedTime(); - cm_log(G1Log::fine(), "[GC concurrent-cleanup-start]"); + cm_log(G1Log::fine(), true, "[GC concurrent-cleanup-start]"); // Now do the concurrent cleanup operation. _cm->completeCleanup(); @@ -227,7 +217,7 @@ g1h->reset_free_regions_coming(); double cleanup_end_sec = os::elapsedTime(); - cm_log(G1Log::fine(), "[GC concurrent-cleanup-end, %1.7lf secs]", cleanup_end_sec - cleanup_start_sec); + 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"); @@ -261,10 +251,7 @@ if (!cm()->has_aborted()) { g1_policy->record_concurrent_mark_cleanup_completed(); } else { - if (G1Log::fine()) { - gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); - gclog_or_tty->print_cr("[GC concurrent-mark-abort]"); - } + cm_log(G1Log::fine(), false, "[GC concurrent-mark-abort]"); } }