< prev index next >
src/share/vm/gc/g1/concurrentMarkThread.cpp
Print this page
@@ -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.inline.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.
< prev index next >