< prev index next >
src/share/vm/gc/g1/concurrentMark.cpp
Print this page
@@ -29,12 +29,10 @@
#include "gc/g1/concurrentMark.inline.hpp"
#include "gc/g1/concurrentMarkThread.inline.hpp"
#include "gc/g1/g1CollectedHeap.inline.hpp"
#include "gc/g1/g1CollectorPolicy.hpp"
#include "gc/g1/g1CollectorState.hpp"
-#include "gc/g1/g1ErgoVerbose.hpp"
-#include "gc/g1/g1Log.hpp"
#include "gc/g1/g1OopClosures.inline.hpp"
#include "gc/g1/g1RemSet.hpp"
#include "gc/g1/g1StringDedup.hpp"
#include "gc/g1/heapRegion.inline.hpp"
#include "gc/g1/heapRegionManager.inline.hpp"
@@ -48,10 +46,11 @@
#include "gc/shared/genOopClosures.inline.hpp"
#include "gc/shared/referencePolicy.hpp"
#include "gc/shared/strongRootsScope.hpp"
#include "gc/shared/taskqueue.inline.hpp"
#include "gc/shared/vmGCOperations.hpp"
+#include "logging/log.hpp"
#include "memory/allocation.hpp"
#include "memory/resourceArea.hpp"
#include "oops/oop.inline.hpp"
#include "runtime/atomic.inline.hpp"
#include "runtime/handles.inline.hpp"
@@ -277,13 +276,11 @@
assert(isEmpty(), "stack should been emptied while handling overflow");
assert(_capacity <= (jint) MarkStackSizeMax, "stack bigger than permitted");
// Clear expansion flag
_should_expand = false;
if (_capacity == (jint) MarkStackSizeMax) {
- if (PrintGCDetails && Verbose) {
- gclog_or_tty->print_cr(" (benign) Can't expand marking stack capacity, at max size limit");
- }
+ log_trace(gc)("(benign) Can't expand marking stack capacity, at max size limit");
return;
}
// Double capacity if possible
jint new_capacity = MIN2(_capacity*2, (jint) MarkStackSizeMax);
// Do not give up existing stack until we have managed to
@@ -299,17 +296,14 @@
}
_base = (oop*)(_virtual_space.low());
_index = 0;
_capacity = new_capacity;
} else {
- if (PrintGCDetails && Verbose) {
// Failed to double capacity, continue;
- gclog_or_tty->print(" (benign) Failed to expand marking stack capacity from "
- SIZE_FORMAT "K to " SIZE_FORMAT "K",
+ log_trace(gc)("(benign) Failed to expand marking stack capacity from " SIZE_FORMAT "K to " SIZE_FORMAT "K",
_capacity / K, new_capacity / K);
}
- }
}
void CMMarkStack::set_should_expand() {
// If we're resetting the marking state because of an
// marking stack overflow, record that we should, if
@@ -574,18 +568,10 @@
_cleanup_task_overhead = marking_task_overhead();
}
_cleanup_sleep_factor =
(1.0 - cleanup_task_overhead()) / cleanup_task_overhead();
-#if 0
- gclog_or_tty->print_cr("Marking Threads %d", parallel_marking_threads());
- gclog_or_tty->print_cr("CM Marking Task Overhead %1.4lf", marking_task_overhead());
- gclog_or_tty->print_cr("CM Sleep Factor %1.4lf", sleep_factor());
- gclog_or_tty->print_cr("CL Marking Task Overhead %1.4lf", cleanup_task_overhead());
- gclog_or_tty->print_cr("CL Sleep Factor %1.4lf", cleanup_sleep_factor());
-#endif
-
_parallel_workers = new WorkGang("G1 Marker",
_max_parallel_marking_threads, false, true);
if (_parallel_workers == NULL) {
vm_exit_during_initialization("Failed necessary allocation.");
} else {
@@ -926,14 +912,11 @@
// we exit this method to abort the pause and restart concurrent
// marking.
reset_marking_state(true /* clear_overflow */);
force_overflow()->update();
- if (G1Log::fine()) {
- gclog_or_tty->gclog_stamp();
- gclog_or_tty->print_cr("[GC concurrent-mark-reset-for-overflow]");
- }
+ log_info(gc)("GC concurrent-mark-reset-for-overflow");
}
}
// after this, each task should reset its own data structures then
// then go into the second barrier
@@ -1100,28 +1083,22 @@
// 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()) {
- if (G1Log::fine()) {
- gclog_or_tty->gclog_stamp();
- gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]");
- }
+ log_info(gc)("GC concurrent-root-region-scan-start");
_parallel_marking_threads = calc_parallel_marking_threads();
assert(parallel_marking_threads() <= max_parallel_marking_threads(),
"Maximum number of marking threads exceeded");
uint active_workers = MAX2(1U, parallel_marking_threads());
CMRootRegionScanTask task(this);
_parallel_workers->set_active_workers(active_workers);
_parallel_workers->run_task(&task);
- if (G1Log::fine()) {
- gclog_or_tty->gclog_stamp();
- gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf secs]", os::elapsedTime() - scan_start);
- }
+ log_info(gc)("GC concurrent-root-region-scan-end, %1.7lf secs", os::elapsedTime() - scan_start);
// It's possible that has_aborted() is true here without actually
// aborting the survivor scan earlier. This is OK as it's
// mainly used for sanity checking.
root_regions()->scan_finished();
@@ -1154,26 +1131,10 @@
_parallel_workers->set_active_workers(active_workers);
_parallel_workers->run_task(&markingTask);
print_stats();
}
-// Helper class to get rid of some boilerplate code.
-class G1CMTraceTime : public StackObj {
- GCTraceTimeImpl _gc_trace_time;
- static bool doit_and_prepend(bool doit) {
- if (doit) {
- gclog_or_tty->put(' ');
- }
- return doit;
- }
-
- public:
- G1CMTraceTime(const char* title, bool doit)
- : _gc_trace_time(title, doit_and_prepend(doit), false, G1CollectedHeap::heap()->gc_timer_cm()) {
- }
-};
-
void ConcurrentMark::checkpointRootsFinal(bool clear_all_soft_refs) {
// world is stopped at this checkpoint
assert(SafepointSynchronize::is_at_safepoint(),
"world should be stopped");
@@ -1188,12 +1149,11 @@
SvcGCMarker sgcm(SvcGCMarker::OTHER);
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
- Universe::verify(VerifyOption_G1UsePrevMarking,
- " VerifyDuringGC:(before)");
+ Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (before)");
}
g1h->check_bitmaps("Remark Start");
G1CollectorPolicy* g1p = g1h->g1_policy();
g1p->record_concurrent_mark_remark_start();
@@ -1207,28 +1167,25 @@
weakRefsWork(clear_all_soft_refs);
if (has_overflown()) {
// Oops. We overflowed. Restart concurrent marking.
_restart_for_overflow = true;
- if (G1TraceMarkStackOverflow) {
- gclog_or_tty->print_cr("\nRemark led to restart for overflow.");
- }
+ log_develop(gc)("Remark led to restart for overflow.");
// Verify the heap w.r.t. the previous marking bitmap.
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
- Universe::verify(VerifyOption_G1UsePrevMarking,
- " VerifyDuringGC:(overflow)");
+ Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (overflow)");
}
// Clear the marking state because we will be restarting
// marking due to overflowing the global mark stack.
reset_marking_state();
} else {
{
- G1CMTraceTime trace("GC aggregate-data", G1Log::finer());
+ GCTraceTime(Debug, gc) trace("GC aggregate-data", g1h->gc_timer_cm());
// Aggregate the per-task counting data that we have accumulated
// while marking.
aggregate_count_data();
}
@@ -1241,12 +1198,11 @@
true /* expected_active */);
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
- Universe::verify(VerifyOption_G1UseNextMarking,
- " VerifyDuringGC:(after)");
+ Universe::verify(VerifyOption_G1UseNextMarking, "During GC (after)");
}
g1h->check_bitmaps("Remark End");
assert(!restart_for_overflow(), "sanity");
// Completely reset the marking state since marking completed
set_non_marking_state();
@@ -1789,12 +1745,11 @@
g1h->verify_region_sets_optional();
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
- Universe::verify(VerifyOption_G1UsePrevMarking,
- " VerifyDuringGC:(before)");
+ Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (before)");
}
g1h->check_bitmaps("Cleanup Start");
G1CollectorPolicy* g1p = g1h->g1_policy();
g1p->record_concurrent_mark_cleanup_start();
@@ -1832,12 +1787,12 @@
double count_end = os::elapsedTime();
double this_final_counting_time = (count_end - start);
_total_counting_time += this_final_counting_time;
- if (G1PrintRegionLivenessInfo) {
- G1PrintRegionLivenessInfoClosure cl(gclog_or_tty, "Post-Marking");
+ if (Log<LOG_TAGS(gc, liveness)>::is_trace()) {
+ G1PrintRegionLivenessInfoClosure cl("Post-Marking");
_g1h->heap_region_iterate(&cl);
}
// Install newly created mark bitMap as "prev".
swapMarkBitMaps();
@@ -1876,23 +1831,18 @@
// Statistics.
double end = os::elapsedTime();
_cleanup_times.add((end - start) * 1000.0);
- if (G1Log::fine()) {
- g1h->g1_policy()->print_heap_transition(start_used_bytes);
- }
-
// Clean up will have freed any regions completely full of garbage.
// Update the soft reference policy with the new heap occupancy.
Universe::update_heap_info_at_gc();
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
- Universe::verify(VerifyOption_G1UsePrevMarking,
- " VerifyDuringGC:(after)");
+ Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (after)");
}
g1h->check_bitmaps("Cleanup End");
g1h->verify_region_sets_optional();
@@ -1921,15 +1871,13 @@
G1CollectedHeap* g1h = G1CollectedHeap::heap();
_cleanup_list.verify_optional();
FreeRegionList tmp_free_list("Tmp Free List");
- if (G1ConcRegionFreeingVerbose) {
- gclog_or_tty->print_cr("G1ConcRegionFreeing [complete cleanup] : "
+ log_develop(gc, freelist)("G1ConcRegionFreeing [complete cleanup] : "
"cleanup list has %u entries",
_cleanup_list.length());
- }
// No one else should be accessing the _cleanup_list at this point,
// so it is not necessary to take any locks
while (!_cleanup_list.is_empty()) {
HeapRegion* hr = _cleanup_list.remove_region(true /* from_head */);
@@ -1943,17 +1891,15 @@
// we do during this process. We'll also append the local list when
// _cleanup_list is empty (which means we just removed the last
// region from the _cleanup_list).
if ((tmp_free_list.length() % G1SecondaryFreeListAppendLength == 0) ||
_cleanup_list.is_empty()) {
- if (G1ConcRegionFreeingVerbose) {
- gclog_or_tty->print_cr("G1ConcRegionFreeing [complete cleanup] : "
+ log_develop(gc, freelist)("G1ConcRegionFreeing [complete cleanup] : "
"appending %u entries to the secondary_free_list, "
"cleanup list still has %u entries",
tmp_free_list.length(),
_cleanup_list.length());
- }
{
MutexLockerEx x(SecondaryFreeList_lock, Mutex::_no_safepoint_check_flag);
g1h->secondary_free_list_add(&tmp_free_list);
SecondaryFreeList_lock->notify_all();
@@ -2206,11 +2152,11 @@
G1CMIsAliveClosure g1_is_alive(g1h);
// Inner scope to exclude the cleaning of the string and symbol
// tables from the displayed time.
{
- G1CMTraceTime t("GC ref-proc", G1Log::finer());
+ GCTraceTime(Debug, gc) trace("GC ref-proc", g1h->gc_timer_cm());
ReferenceProcessor* rp = g1h->ref_processor_cm();
// See the comment in G1CollectedHeap::ref_processing_init()
// about how reference processing currently works in G1.
@@ -2296,28 +2242,28 @@
assert(_markStack.isEmpty(), "Marking should have completed");
// Unload Klasses, String, Symbols, Code Cache, etc.
{
- G1CMTraceTime trace("Unloading", G1Log::finer());
+ GCTraceTime(Debug, gc) trace("Unloading", g1h->gc_timer_cm());
if (ClassUnloadingWithConcurrentMark) {
bool purged_classes;
{
- G1CMTraceTime trace("System Dictionary Unloading", G1Log::finest());
+ GCTraceTime(Trace, gc) trace("System Dictionary Unloading", g1h->gc_timer_cm());
purged_classes = SystemDictionary::do_unloading(&g1_is_alive, false /* Defer klass cleaning */);
}
{
- G1CMTraceTime trace("Parallel Unloading", G1Log::finest());
+ GCTraceTime(Trace, gc) trace("Parallel Unloading", g1h->gc_timer_cm());
weakRefsWorkParallelPart(&g1_is_alive, purged_classes);
}
}
if (G1StringDedup::is_enabled()) {
- G1CMTraceTime trace("String Deduplication Unlink", G1Log::finest());
+ GCTraceTime(Trace, gc) trace("String Deduplication Unlink", g1h->gc_timer_cm());
G1StringDedup::unlink(&g1_is_alive);
}
}
}
@@ -2434,11 +2380,11 @@
void ConcurrentMark::checkpointRootsFinalWork() {
ResourceMark rm;
HandleMark hm;
G1CollectedHeap* g1h = G1CollectedHeap::heap();
- G1CMTraceTime trace("Finalize Marking", G1Log::finer());
+ GCTraceTime(Debug, gc) trace("Finalize Marking", g1h->gc_timer_cm());
g1h->ensure_parsability(false);
// this is remark, so we'll use up all active threads
uint active_workers = g1h->workers()->active_workers();
@@ -2792,16 +2738,18 @@
task_card_bm->clear();
}
}
void ConcurrentMark::print_stats() {
- if (G1MarkingVerboseLevel > 0) {
- gclog_or_tty->print_cr("---------------------------------------------------------------------");
+ LogHandle(gc, stats) log;
+ if (!log.is_debug()) {
+ return;
+ }
+ log.debug("---------------------------------------------------------------------");
for (size_t i = 0; i < _active_tasks; ++i) {
_tasks[i]->print_stats();
- gclog_or_tty->print_cr("---------------------------------------------------------------------");
- }
+ log.debug("---------------------------------------------------------------------");
}
}
// abandon current marking iteration due to a Full GC
void ConcurrentMark::abort() {
@@ -2841,47 +2789,43 @@
_g1h->register_concurrent_cycle_end();
}
static void print_ms_time_info(const char* prefix, const char* name,
NumberSeq& ns) {
- gclog_or_tty->print_cr("%s%5d %12s: total time = %8.2f s (avg = %8.2f ms).",
+ log_trace(gc, marking, stats, exit)("%s%5d %12s: total time = %8.2f s (avg = %8.2f ms).",
prefix, ns.num(), name, ns.sum()/1000.0, ns.avg());
if (ns.num() > 0) {
- gclog_or_tty->print_cr("%s [std. dev = %8.2f ms, max = %8.2f ms]",
+ log_trace(gc, marking, stats, exit)("%s [std. dev = %8.2f ms, max = %8.2f ms]",
prefix, ns.sd(), ns.maximum());
}
}
void ConcurrentMark::print_summary_info() {
- gclog_or_tty->print_cr(" Concurrent marking:");
+ LogHandle(gc, marking, stats, exit) log;
+ if (!log.is_trace()) {
+ return;
+ }
+
+ log.trace(" Concurrent marking:");
print_ms_time_info(" ", "init marks", _init_times);
print_ms_time_info(" ", "remarks", _remark_times);
{
print_ms_time_info(" ", "final marks", _remark_mark_times);
print_ms_time_info(" ", "weak refs", _remark_weak_ref_times);
}
print_ms_time_info(" ", "cleanups", _cleanup_times);
- gclog_or_tty->print_cr(" Final counting total time = %8.2f s (avg = %8.2f ms).",
- _total_counting_time,
- (_cleanup_times.num() > 0 ? _total_counting_time * 1000.0 /
- (double)_cleanup_times.num()
- : 0.0));
+ log.trace(" Final counting total time = %8.2f s (avg = %8.2f ms).",
+ _total_counting_time, (_cleanup_times.num() > 0 ? _total_counting_time * 1000.0 / (double)_cleanup_times.num() : 0.0));
if (G1ScrubRemSets) {
- gclog_or_tty->print_cr(" RS scrub total time = %8.2f s (avg = %8.2f ms).",
- _total_rs_scrub_time,
- (_cleanup_times.num() > 0 ? _total_rs_scrub_time * 1000.0 /
- (double)_cleanup_times.num()
- : 0.0));
- }
- gclog_or_tty->print_cr(" Total stop_world time = %8.2f s.",
- (_init_times.sum() + _remark_times.sum() +
- _cleanup_times.sum())/1000.0);
- gclog_or_tty->print_cr(" Total concurrent time = %8.2f s "
- "(%8.2f s marking).",
- cmThread()->vtime_accum(),
- cmThread()->vtime_mark_accum());
+ log.trace(" RS scrub total time = %8.2f s (avg = %8.2f ms).",
+ _total_rs_scrub_time, (_cleanup_times.num() > 0 ? _total_rs_scrub_time * 1000.0 / (double)_cleanup_times.num() : 0.0));
+ }
+ log.trace(" Total stop_world time = %8.2f s.",
+ (_init_times.sum() + _remark_times.sum() + _cleanup_times.sum())/1000.0);
+ log.trace(" Total concurrent time = %8.2f s (%8.2f s marking).",
+ cmThread()->vtime_accum(), cmThread()->vtime_mark_accum());
}
void ConcurrentMark::print_worker_threads_on(outputStream* st) const {
_parallel_workers->print_worker_threads_on(st);
}
@@ -3259,18 +3203,18 @@
// limits to get the regular clock call early
decrease_limits();
}
void CMTask::print_stats() {
- gclog_or_tty->print_cr("Marking Stats, task = %u, calls = %d",
+ log_debug(gc, stats)("Marking Stats, task = %u, calls = %d",
_worker_id, _calls);
- gclog_or_tty->print_cr(" Elapsed time = %1.2lfms, Termination time = %1.2lfms",
+ log_debug(gc, stats)(" Elapsed time = %1.2lfms, Termination time = %1.2lfms",
_elapsed_time_ms, _termination_time_ms);
- gclog_or_tty->print_cr(" Step Times (cum): num = %d, avg = %1.2lfms, sd = %1.2lfms",
+ log_debug(gc, stats)(" Step Times (cum): num = %d, avg = %1.2lfms, sd = %1.2lfms",
_step_times_ms.num(), _step_times_ms.avg(),
_step_times_ms.sd());
- gclog_or_tty->print_cr(" max = %1.2lfms, total = %1.2lfms",
+ log_debug(gc, stats)(" max = %1.2lfms, total = %1.2lfms",
_step_times_ms.maximum(), _step_times_ms.sum());
}
bool ConcurrentMark::try_stealing(uint worker_id, int* hash_seed, oop& obj) {
return _task_queues->steal(worker_id, hash_seed, obj);
@@ -3776,31 +3720,29 @@
#define G1PPRL_SUM_BYTE_FORMAT(tag) " " tag ": " SIZE_FORMAT
#define G1PPRL_SUM_MB_FORMAT(tag) " " tag ": %1.2f MB"
#define G1PPRL_SUM_MB_PERC_FORMAT(tag) G1PPRL_SUM_MB_FORMAT(tag) " / %1.2f %%"
G1PrintRegionLivenessInfoClosure::
-G1PrintRegionLivenessInfoClosure(outputStream* out, const char* phase_name)
- : _out(out),
- _total_used_bytes(0), _total_capacity_bytes(0),
+G1PrintRegionLivenessInfoClosure(const char* phase_name)
+ : _total_used_bytes(0), _total_capacity_bytes(0),
_total_prev_live_bytes(0), _total_next_live_bytes(0),
_hum_used_bytes(0), _hum_capacity_bytes(0),
_hum_prev_live_bytes(0), _hum_next_live_bytes(0),
_total_remset_bytes(0), _total_strong_code_roots_bytes(0) {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
MemRegion g1_reserved = g1h->g1_reserved();
double now = os::elapsedTime();
// Print the header of the output.
- _out->cr();
- _out->print_cr(G1PPRL_LINE_PREFIX" PHASE %s @ %1.3f", phase_name, now);
- _out->print_cr(G1PPRL_LINE_PREFIX" HEAP"
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX" PHASE %s @ %1.3f", phase_name, now);
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX" HEAP"
G1PPRL_SUM_ADDR_FORMAT("reserved")
G1PPRL_SUM_BYTE_FORMAT("region-size"),
p2i(g1_reserved.start()), p2i(g1_reserved.end()),
HeapRegion::GrainBytes);
- _out->print_cr(G1PPRL_LINE_PREFIX);
- _out->print_cr(G1PPRL_LINE_PREFIX
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX);
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_H_FORMAT
G1PPRL_ADDR_BASE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
@@ -3808,11 +3750,11 @@
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT,
"type", "address-range",
"used", "prev-live", "next-live", "gc-eff",
"remset", "code-roots");
- _out->print_cr(G1PPRL_LINE_PREFIX
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_H_FORMAT
G1PPRL_ADDR_BASE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
@@ -3890,11 +3832,11 @@
_total_next_live_bytes += next_live_bytes;
_total_remset_bytes += remset_bytes;
_total_strong_code_roots_bytes += strong_code_roots_bytes;
// Print a line for this particular region.
- _out->print_cr(G1PPRL_LINE_PREFIX
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_FORMAT
G1PPRL_ADDR_BASE_FORMAT
G1PPRL_BYTE_FORMAT
G1PPRL_BYTE_FORMAT
G1PPRL_BYTE_FORMAT
@@ -3910,12 +3852,12 @@
G1PrintRegionLivenessInfoClosure::~G1PrintRegionLivenessInfoClosure() {
// add static memory usages to remembered set sizes
_total_remset_bytes += HeapRegionRemSet::fl_mem_size() + HeapRegionRemSet::static_mem_size();
// Print the footer of the output.
- _out->print_cr(G1PPRL_LINE_PREFIX);
- _out->print_cr(G1PPRL_LINE_PREFIX
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX);
+ log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
" SUMMARY"
G1PPRL_SUM_MB_FORMAT("capacity")
G1PPRL_SUM_MB_PERC_FORMAT("used")
G1PPRL_SUM_MB_PERC_FORMAT("prev-live")
G1PPRL_SUM_MB_PERC_FORMAT("next-live")
@@ -3928,7 +3870,6 @@
perc(_total_prev_live_bytes, _total_capacity_bytes),
bytes_to_mb(_total_next_live_bytes),
perc(_total_next_live_bytes, _total_capacity_bytes),
bytes_to_mb(_total_remset_bytes),
bytes_to_mb(_total_strong_code_roots_bytes));
- _out->cr();
}
< prev index next >