< prev index next >
src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp
Print this page
@@ -51,10 +51,11 @@
#include "gc/shared/genOopClosures.inline.hpp"
#include "gc/shared/isGCActiveMark.hpp"
#include "gc/shared/referencePolicy.hpp"
#include "gc/shared/strongRootsScope.hpp"
#include "gc/shared/taskqueue.inline.hpp"
+#include "logging/log.hpp"
#include "memory/allocation.hpp"
#include "memory/iterator.inline.hpp"
#include "memory/padded.hpp"
#include "memory/resourceArea.hpp"
#include "oops/oop.inline.hpp"
@@ -364,17 +365,14 @@
// Apply a further correction factor which tries to adjust
// for recent occurance of concurrent mode failures.
cms_adjustment = cms_adjustment * cms_free_adjustment_factor(cms_free);
cms_free_dbl = cms_free_dbl * cms_adjustment;
- if (PrintGCDetails && Verbose) {
- gclog_or_tty->print_cr("CMSStats::time_until_cms_gen_full: cms_free "
- SIZE_FORMAT " expected_promotion " SIZE_FORMAT,
+ log_trace(gc, stats)("CMSStats::time_until_cms_gen_full: cms_free " SIZE_FORMAT " expected_promotion " SIZE_FORMAT,
cms_free, expected_promotion);
- gclog_or_tty->print_cr(" cms_free_dbl %f cms_consumption_rate %f",
+ log_trace(gc, stats)(" cms_free_dbl %f cms_consumption_rate %f",
cms_free_dbl, cms_consumption_rate() + 1.0);
- }
// Add 1 in case the consumption rate goes to zero.
return cms_free_dbl / (cms_consumption_rate() + 1.0);
}
return 0.0;
}
@@ -399,16 +397,12 @@
double work = cms_duration() + gc0_period();
double deadline = time_until_cms_gen_full();
// If a concurrent mode failure occurred recently, we want to be
// more conservative and halve our expected time_until_cms_gen_full()
if (work > deadline) {
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print(
- " CMSCollector: collect because of anticipated promotion "
- "before full %3.7f + %3.7f > %3.7f ", cms_duration(),
- gc0_period(), time_until_cms_gen_full());
- }
+ log_develop(gc)("CMSCollector: collect because of anticipated promotion before full %3.7f + %3.7f > %3.7f ",
+ cms_duration(), gc0_period(), time_until_cms_gen_full());
return 0.0;
}
return work - deadline;
}
@@ -666,35 +660,10 @@
void ConcurrentMarkSweepGeneration::print_statistics() {
cmsSpace()->printFLCensus(0);
}
#endif
-void ConcurrentMarkSweepGeneration::printOccupancy(const char *s) {
- GenCollectedHeap* gch = GenCollectedHeap::heap();
- if (PrintGCDetails) {
- // I didn't want to change the logging when removing the level concept,
- // but I guess this logging could say "old" or something instead of "1".
- assert(gch->is_old_gen(this),
- "The CMS generation should be the old generation");
- uint level = 1;
- if (Verbose) {
- gclog_or_tty->print("[%u %s-%s: " SIZE_FORMAT "(" SIZE_FORMAT ")]",
- level, short_name(), s, used(), capacity());
- } else {
- gclog_or_tty->print("[%u %s-%s: " SIZE_FORMAT "K(" SIZE_FORMAT "K)]",
- level, short_name(), s, used() / K, capacity() / K);
- }
- }
- if (Verbose) {
- gclog_or_tty->print(" " SIZE_FORMAT "(" SIZE_FORMAT ")",
- gch->used(), gch->capacity());
- } else {
- gclog_or_tty->print(" " SIZE_FORMAT "K(" SIZE_FORMAT "K)",
- gch->used() / K, gch->capacity() / K);
- }
-}
-
size_t
ConcurrentMarkSweepGeneration::contiguous_available() const {
// dld proposes an improvement in precision here. If the committed
// part of the space ends in a free block we should add that to
// uncommitted size in the calculation below. Will make this
@@ -714,25 +683,22 @@
bool ConcurrentMarkSweepGeneration::promotion_attempt_is_safe(size_t max_promotion_in_bytes) const {
size_t available = max_available();
size_t av_promo = (size_t)gc_stats()->avg_promoted()->padded_average();
bool res = (available >= av_promo) || (available >= max_promotion_in_bytes);
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print_cr(
- "CMS: promo attempt is%s safe: available(" SIZE_FORMAT ") %s av_promo(" SIZE_FORMAT "),"
- "max_promo(" SIZE_FORMAT ")",
- res? "":" not", available, res? ">=":"<",
- av_promo, max_promotion_in_bytes);
- }
+ log_trace(gc, promotion)("CMS: promo attempt is%s safe: available(" SIZE_FORMAT ") %s av_promo(" SIZE_FORMAT "), max_promo(" SIZE_FORMAT ")",
+ res? "":" not", available, res? ">=":"<", av_promo, max_promotion_in_bytes);
return res;
}
// At a promotion failure dump information on block layout in heap
// (cms old generation).
void ConcurrentMarkSweepGeneration::promotion_failure_occurred() {
- if (CMSDumpAtPromotionFailure) {
- cmsSpace()->dump_at_safepoint_with_locks(collector(), gclog_or_tty);
+ LogHandle(gc, promotion) log;
+ if (log.is_trace()) {
+ ResourceMark rm;
+ cmsSpace()->dump_at_safepoint_with_locks(collector(), log.trace_stream());
}
}
void ConcurrentMarkSweepGeneration::reset_after_compaction() {
// Clear the promotion information. These pointers can be adjusted
@@ -784,31 +750,30 @@
// compute expansion delta needed for reaching desired free percentage
if (free_percentage < desired_free_percentage) {
size_t desired_capacity = (size_t)(used() / ((double) 1 - desired_free_percentage));
assert(desired_capacity >= capacity(), "invalid expansion size");
size_t expand_bytes = MAX2(desired_capacity - capacity(), MinHeapDeltaBytes);
- if (PrintGCDetails && Verbose) {
+ LogHandle(gc) log;
+ if (log.is_trace()) {
size_t desired_capacity = (size_t)(used() / ((double) 1 - desired_free_percentage));
- gclog_or_tty->print_cr("\nFrom compute_new_size: ");
- gclog_or_tty->print_cr(" Free fraction %f", free_percentage);
- gclog_or_tty->print_cr(" Desired free fraction %f", desired_free_percentage);
- gclog_or_tty->print_cr(" Maximum free fraction %f", maximum_free_percentage);
- gclog_or_tty->print_cr(" Capacity " SIZE_FORMAT, capacity() / 1000);
- gclog_or_tty->print_cr(" Desired capacity " SIZE_FORMAT, desired_capacity / 1000);
+ log.trace("From compute_new_size: ");
+ log.trace(" Free fraction %f", free_percentage);
+ log.trace(" Desired free fraction %f", desired_free_percentage);
+ log.trace(" Maximum free fraction %f", maximum_free_percentage);
+ log.trace(" Capacity " SIZE_FORMAT, capacity() / 1000);
+ log.trace(" Desired capacity " SIZE_FORMAT, desired_capacity / 1000);
GenCollectedHeap* gch = GenCollectedHeap::heap();
assert(gch->is_old_gen(this), "The CMS generation should always be the old generation");
size_t young_size = gch->young_gen()->capacity();
- gclog_or_tty->print_cr(" Young gen size " SIZE_FORMAT, young_size / 1000);
- gclog_or_tty->print_cr(" unsafe_max_alloc_nogc " SIZE_FORMAT, unsafe_max_alloc_nogc() / 1000);
- gclog_or_tty->print_cr(" contiguous available " SIZE_FORMAT, contiguous_available() / 1000);
- gclog_or_tty->print_cr(" Expand by " SIZE_FORMAT " (bytes)", expand_bytes);
+ log.trace(" Young gen size " SIZE_FORMAT, young_size / 1000);
+ log.trace(" unsafe_max_alloc_nogc " SIZE_FORMAT, unsafe_max_alloc_nogc() / 1000);
+ log.trace(" contiguous available " SIZE_FORMAT, contiguous_available() / 1000);
+ log.trace(" Expand by " SIZE_FORMAT " (bytes)", expand_bytes);
}
// safe if expansion fails
expand_for_gc_cause(expand_bytes, 0, CMSExpansionCause::_satisfy_free_ratio);
- if (PrintGCDetails && Verbose) {
- gclog_or_tty->print_cr(" Expanded free fraction %f", ((double) free()) / capacity());
- }
+ log.trace(" Expanded free fraction %f", ((double) free()) / capacity());
} else {
size_t desired_capacity = (size_t)(used() / ((double) 1 - desired_free_percentage));
assert(desired_capacity <= capacity(), "invalid expansion size");
size_t shrink_bytes = capacity() - desired_capacity;
// Don't shrink unless the delta is greater than the minimum shrink we want
@@ -1142,39 +1107,33 @@
// hip and should be fixed by untying them.
}
bool CMSCollector::shouldConcurrentCollect() {
if (_full_gc_requested) {
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print_cr("CMSCollector: collect because of explicit "
- " gc request (or gc_locker)");
- }
+ log_trace(gc)("CMSCollector: collect because of explicit gc request (or gc_locker)");
return true;
}
FreelistLocker x(this);
// ------------------------------------------------------------------
// Print out lots of information which affects the initiation of
// a collection.
- if (PrintCMSInitiationStatistics && stats().valid()) {
- gclog_or_tty->print("CMSCollector shouldConcurrentCollect: ");
- gclog_or_tty->stamp();
- gclog_or_tty->cr();
- stats().print_on(gclog_or_tty);
- gclog_or_tty->print_cr("time_until_cms_gen_full %3.7f",
- stats().time_until_cms_gen_full());
- gclog_or_tty->print_cr("free=" SIZE_FORMAT, _cmsGen->free());
- gclog_or_tty->print_cr("contiguous_available=" SIZE_FORMAT,
- _cmsGen->contiguous_available());
- gclog_or_tty->print_cr("promotion_rate=%g", stats().promotion_rate());
- gclog_or_tty->print_cr("cms_allocation_rate=%g", stats().cms_allocation_rate());
- gclog_or_tty->print_cr("occupancy=%3.7f", _cmsGen->occupancy());
- gclog_or_tty->print_cr("initiatingOccupancy=%3.7f", _cmsGen->initiating_occupancy());
- gclog_or_tty->print_cr("cms_time_since_begin=%3.7f", stats().cms_time_since_begin());
- gclog_or_tty->print_cr("cms_time_since_end=%3.7f", stats().cms_time_since_end());
- gclog_or_tty->print_cr("metadata initialized %d",
- MetaspaceGC::should_concurrent_collect());
+ LogHandle(gc, stats) log;
+ if (log.is_debug() && stats().valid()) {
+ log.debug("CMSCollector shouldConcurrentCollect: ");
+ ResourceMark rm;
+ stats().print_on(log.debug_stream());
+ log.debug("time_until_cms_gen_full %3.7f", stats().time_until_cms_gen_full());
+ log.debug("free=" SIZE_FORMAT, _cmsGen->free());
+ log.debug("contiguous_available=" SIZE_FORMAT, _cmsGen->contiguous_available());
+ log.debug("promotion_rate=%g", stats().promotion_rate());
+ log.debug("cms_allocation_rate=%g", stats().cms_allocation_rate());
+ log.debug("occupancy=%3.7f", _cmsGen->occupancy());
+ log.debug("initiatingOccupancy=%3.7f", _cmsGen->initiating_occupancy());
+ log.debug("cms_time_since_begin=%3.7f", stats().cms_time_since_begin());
+ log.debug("cms_time_since_end=%3.7f", stats().cms_time_since_end());
+ log.debug("metadata initialized %d", MetaspaceGC::should_concurrent_collect());
}
// ------------------------------------------------------------------
// If the estimated time to complete a cms collection (cms_duration())
// is less than the estimated time remaining until the cms generation
@@ -1188,16 +1147,12 @@
// We want to conservatively collect somewhat early in order
// to try and "bootstrap" our CMS/promotion statistics;
// this branch will not fire after the first successful CMS
// collection because the stats should then be valid.
if (_cmsGen->occupancy() >= _bootstrap_occupancy) {
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print_cr(
- " CMSCollector: collect for bootstrapping statistics:"
- " occupancy = %f, boot occupancy = %f", _cmsGen->occupancy(),
- _bootstrap_occupancy);
- }
+ log_trace(gc)(" CMSCollector: collect for bootstrapping statistics: occupancy = %f, boot occupancy = %f",
+ _cmsGen->occupancy(), _bootstrap_occupancy);
return true;
}
}
}
@@ -1205,33 +1160,27 @@
// old gen want a collection cycle started. Each may use
// an appropriate criterion for making this decision.
// XXX We need to make sure that the gen expansion
// criterion dovetails well with this. XXX NEED TO FIX THIS
if (_cmsGen->should_concurrent_collect()) {
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print_cr("CMS old gen initiated");
- }
+ log_trace(gc)("CMS old gen initiated");
return true;
}
// We start a collection if we believe an incremental collection may fail;
// this is not likely to be productive in practice because it's probably too
// late anyway.
GenCollectedHeap* gch = GenCollectedHeap::heap();
assert(gch->collector_policy()->is_generation_policy(),
"You may want to check the correctness of the following");
if (gch->incremental_collection_will_fail(true /* consult_young */)) {
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print("CMSCollector: collect because incremental collection will fail ");
- }
+ log_trace(gc)("CMSCollector: collect because incremental collection will fail ");
return true;
}
if (MetaspaceGC::should_concurrent_collect()) {
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print("CMSCollector: collect for metadata allocation ");
- }
+ log_trace(gc)("CMSCollector: collect for metadata allocation ");
return true;
}
// CMSTriggerInterval starts a CMS cycle if enough time has passed.
if (CMSTriggerInterval >= 0) {
@@ -1241,17 +1190,15 @@
}
// Check the CMS time since begin (we do not check the stats validity
// as we want to be able to trigger the first CMS cycle as well)
if (stats().cms_time_since_begin() >= (CMSTriggerInterval / ((double) MILLIUNITS))) {
- if (Verbose && PrintGCDetails) {
if (stats().valid()) {
- gclog_or_tty->print_cr("CMSCollector: collect because of trigger interval (time since last begin %3.7f secs)",
+ log_trace(gc)("CMSCollector: collect because of trigger interval (time since last begin %3.7f secs)",
stats().cms_time_since_begin());
} else {
- gclog_or_tty->print_cr("CMSCollector: collect because of trigger interval (first collection)");
- }
+ log_trace(gc)("CMSCollector: collect because of trigger interval (first collection)");
}
return true;
}
}
@@ -1290,24 +1237,19 @@
// we will be out of sufficient free space given allocation rate estimates.]
bool ConcurrentMarkSweepGeneration::should_concurrent_collect() const {
assert_lock_strong(freelistLock());
if (occupancy() > initiating_occupancy()) {
- if (PrintGCDetails && Verbose) {
- gclog_or_tty->print(" %s: collect because of occupancy %f / %f ",
+ log_trace(gc)(" %s: collect because of occupancy %f / %f ",
short_name(), occupancy(), initiating_occupancy());
- }
return true;
}
if (UseCMSInitiatingOccupancyOnly) {
return false;
}
if (expansion_cause() == CMSExpansionCause::_satisfy_allocation) {
- if (PrintGCDetails && Verbose) {
- gclog_or_tty->print(" %s: collect because expanded for allocation ",
- short_name());
- }
+ log_trace(gc)(" %s: collect because expanded for allocation ", short_name());
return true;
}
return false;
}
@@ -1360,17 +1302,13 @@
GCCause::is_serviceability_requested_gc(cause);
}
void CMSCollector::report_concurrent_mode_interruption() {
if (is_external_interruption()) {
- if (PrintGCDetails) {
- gclog_or_tty->print(" (concurrent mode interrupted)");
- }
+ log_debug(gc)("Concurrent mode interrupted");
} else {
- if (PrintGCDetails) {
- gclog_or_tty->print(" (concurrent mode failure)");
- }
+ log_debug(gc)("Concurrent mode failure");
_gc_tracer_cm->report_concurrent_mode_failure();
}
}
@@ -1500,15 +1438,13 @@
// The CMS_token is already held. Get back the other locks.
assert(ConcurrentMarkSweepThread::vm_thread_has_cms_token(),
"VM thread should have CMS token");
getFreelistLocks();
bitMapLock()->lock_without_safepoint_check();
- if (TraceCMSState) {
- gclog_or_tty->print_cr("CMS foreground collector has asked for control "
- INTPTR_FORMAT " with first state %d", p2i(Thread::current()), first_state);
- gclog_or_tty->print_cr(" gets control with state %d", _collectorState);
- }
+ log_debug(gc, state)("CMS foreground collector has asked for control " INTPTR_FORMAT " with first state %d",
+ p2i(Thread::current()), first_state);
+ log_debug(gc, state)(" gets control with state %d", _collectorState);
// Inform cms gen if this was due to partial collection failing.
// The CMS gen may use this fact to determine its expansion policy.
GenCollectedHeap* gch = GenCollectedHeap::heap();
if (gch->incremental_collection_will_fail(false /* don't consult_young */)) {
@@ -1578,11 +1514,11 @@
gc_timer->register_gc_start();
SerialOldTracer* gc_tracer = GenMarkSweep::gc_tracer();
gc_tracer->report_gc_start(gch->gc_cause(), gc_timer->gc_start());
- GCTraceTime t("CMS:MSC ", PrintGCDetails && Verbose, true, NULL);
+ GCTraceTime(Trace, gc) t("CMS:MSC");
// Temporarily widen the span of the weak reference processing to
// the entire heap.
MemRegion new_span(GenCollectedHeap::heap()->reserved_region());
ReferenceProcessorSpanMutator rp_mut_span(ref_processor(), new_span);
@@ -1663,37 +1599,38 @@
// For a mark-sweep-compact, compute_new_size() will be called
// in the heap's do_collection() method.
}
void CMSCollector::print_eden_and_survivor_chunk_arrays() {
+ LogHandle(gc, heap) log;
+ if (!log.is_trace()) {
+ return;
+ }
+
ContiguousSpace* eden_space = _young_gen->eden();
ContiguousSpace* from_space = _young_gen->from();
ContiguousSpace* to_space = _young_gen->to();
// Eden
if (_eden_chunk_array != NULL) {
- gclog_or_tty->print_cr("eden " PTR_FORMAT "-" PTR_FORMAT "-" PTR_FORMAT "(" SIZE_FORMAT ")",
+ log.trace("eden " PTR_FORMAT "-" PTR_FORMAT "-" PTR_FORMAT "(" SIZE_FORMAT ")",
p2i(eden_space->bottom()), p2i(eden_space->top()),
p2i(eden_space->end()), eden_space->capacity());
- gclog_or_tty->print_cr("_eden_chunk_index=" SIZE_FORMAT ", "
- "_eden_chunk_capacity=" SIZE_FORMAT,
+ log.trace("_eden_chunk_index=" SIZE_FORMAT ", _eden_chunk_capacity=" SIZE_FORMAT,
_eden_chunk_index, _eden_chunk_capacity);
for (size_t i = 0; i < _eden_chunk_index; i++) {
- gclog_or_tty->print_cr("_eden_chunk_array[" SIZE_FORMAT "]=" PTR_FORMAT,
- i, p2i(_eden_chunk_array[i]));
+ log.trace("_eden_chunk_array[" SIZE_FORMAT "]=" PTR_FORMAT, i, p2i(_eden_chunk_array[i]));
}
}
// Survivor
if (_survivor_chunk_array != NULL) {
- gclog_or_tty->print_cr("survivor " PTR_FORMAT "-" PTR_FORMAT "-" PTR_FORMAT "(" SIZE_FORMAT ")",
+ log.trace("survivor " PTR_FORMAT "-" PTR_FORMAT "-" PTR_FORMAT "(" SIZE_FORMAT ")",
p2i(from_space->bottom()), p2i(from_space->top()),
p2i(from_space->end()), from_space->capacity());
- gclog_or_tty->print_cr("_survivor_chunk_index=" SIZE_FORMAT ", "
- "_survivor_chunk_capacity=" SIZE_FORMAT,
+ log.trace("_survivor_chunk_index=" SIZE_FORMAT ", _survivor_chunk_capacity=" SIZE_FORMAT,
_survivor_chunk_index, _survivor_chunk_capacity);
for (size_t i = 0; i < _survivor_chunk_index; i++) {
- gclog_or_tty->print_cr("_survivor_chunk_array[" SIZE_FORMAT "]=" PTR_FORMAT,
- i, p2i(_survivor_chunk_array[i]));
+ log.trace("_survivor_chunk_array[" SIZE_FORMAT "]=" PTR_FORMAT, i, p2i(_survivor_chunk_array[i]));
}
}
}
void CMSCollector::getFreelistLocks() const {
@@ -1778,29 +1715,23 @@
// Signal that we are about to start a collection
gch->increment_total_full_collections(); // ... starting a collection cycle
_collection_count_start = gch->total_full_collections();
}
- // Used for PrintGC
- size_t prev_used = 0;
- if (PrintGC && Verbose) {
- prev_used = _cmsGen->used();
- }
+ size_t prev_used = _cmsGen->used();
// The change of the collection state is normally done at this level;
// the exceptions are phases that are executed while the world is
// stopped. For those phases the change of state is done while the
// world is stopped. For baton passing purposes this allows the
// background collector to finish the phase and change state atomically.
// The foreground collector cannot wait on a phase that is done
// while the world is stopped because the foreground collector already
// has the world stopped and would deadlock.
while (_collectorState != Idling) {
- if (TraceCMSState) {
- gclog_or_tty->print_cr("Thread " INTPTR_FORMAT " in CMS state %d",
+ log_debug(gc, state)("Thread " INTPTR_FORMAT " in CMS state %d",
p2i(Thread::current()), _collectorState);
- }
// The foreground collector
// holds the Heap_lock throughout its collection.
// holds the CMS token (but not the lock)
// except while it is waiting for the background collector to yield.
//
@@ -1826,15 +1757,12 @@
if (waitForForegroundGC()) {
// We yielded to a foreground GC, nothing more to be
// done this round.
assert(_foregroundGCShouldWait == false, "We set it to false in "
"waitForForegroundGC()");
- if (TraceCMSState) {
- gclog_or_tty->print_cr("CMS Thread " INTPTR_FORMAT
- " exiting collection CMS state %d",
+ log_debug(gc, state)("CMS Thread " INTPTR_FORMAT " exiting collection CMS state %d",
p2i(Thread::current()), _collectorState);
- }
return;
} else {
// The background collector can run but check to see if the
// foreground collector has done a collection while the
// background collector was waiting to get the CGC_lock
@@ -1934,14 +1862,12 @@
case Idling:
default:
ShouldNotReachHere();
break;
}
- if (TraceCMSState) {
- gclog_or_tty->print_cr(" Thread " INTPTR_FORMAT " done - next CMS state %d",
+ log_debug(gc, state)(" Thread " INTPTR_FORMAT " done - next CMS state %d",
p2i(Thread::current()), _collectorState);
- }
assert(_foregroundGCShouldWait, "block post-condition");
}
// Should this be in gc_epilogue?
collector_policy()->counters()->update_counters();
@@ -1956,18 +1882,14 @@
CGC_lock->notify();
}
assert(!ConcurrentMarkSweepThread::cms_thread_has_cms_token(),
"Possible deadlock");
}
- if (TraceCMSState) {
- gclog_or_tty->print_cr("CMS Thread " INTPTR_FORMAT
- " exiting collection CMS state %d",
+ log_debug(gc, state)("CMS Thread " INTPTR_FORMAT " exiting collection CMS state %d",
p2i(Thread::current()), _collectorState);
- }
- if (PrintGC && Verbose) {
- _cmsGen->print_heap_change(prev_used);
- }
+ log_info(gc, heap)("Old: " SIZE_FORMAT "K->" SIZE_FORMAT "K(" SIZE_FORMAT "K)",
+ prev_used / K, _cmsGen->used()/K, _cmsGen->capacity() /K);
}
void CMSCollector::register_gc_start(GCCause::Cause cause) {
_cms_start_registered = true;
_gc_timer_cm->register_gc_start();
@@ -2015,26 +1937,22 @@
ConcurrentMarkSweepThread::CMS_cms_has_token);
ConcurrentMarkSweepThread::set_CMS_flag(
ConcurrentMarkSweepThread::CMS_cms_wants_token);
// Get a possibly blocked foreground thread going
CGC_lock->notify();
- if (TraceCMSState) {
- gclog_or_tty->print_cr("CMS Thread " INTPTR_FORMAT " waiting at CMS state %d",
+ log_debug(gc, state)("CMS Thread " INTPTR_FORMAT " waiting at CMS state %d",
p2i(Thread::current()), _collectorState);
- }
while (_foregroundGCIsActive) {
CGC_lock->wait(Mutex::_no_safepoint_check_flag);
}
ConcurrentMarkSweepThread::set_CMS_flag(
ConcurrentMarkSweepThread::CMS_cms_has_token);
ConcurrentMarkSweepThread::clear_CMS_flag(
ConcurrentMarkSweepThread::CMS_cms_wants_token);
}
- if (TraceCMSState) {
- gclog_or_tty->print_cr("CMS Thread " INTPTR_FORMAT " continuing at CMS state %d",
+ log_debug(gc, state)("CMS Thread " INTPTR_FORMAT " continuing at CMS state %d",
p2i(Thread::current()), _collectorState);
- }
return res;
}
// Because of the need to lock the free lists and other structures in
// the collector, common to all the generations that the collector is
@@ -2127,15 +2045,12 @@
cmsSpace()->gc_prologue();
// Clear stat counters
NOT_PRODUCT(
assert(_numObjectsPromoted == 0, "check");
assert(_numWordsPromoted == 0, "check");
- if (Verbose && PrintGC) {
- gclog_or_tty->print("Allocated " SIZE_FORMAT " objects, "
- SIZE_FORMAT " bytes concurrently",
+ log_develop(gc, alloc)("Allocated " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes concurrently",
_numObjectsAllocated, _numWordsAllocated*sizeof(HeapWord));
- }
_numObjectsAllocated = 0;
_numWordsAllocated = 0;
)
}
@@ -2208,25 +2123,19 @@
cmsSpace()->gc_epilogue();
// Print stat counters
NOT_PRODUCT(
assert(_numObjectsAllocated == 0, "check");
assert(_numWordsAllocated == 0, "check");
- if (Verbose && PrintGC) {
- gclog_or_tty->print("Promoted " SIZE_FORMAT " objects, "
- SIZE_FORMAT " bytes",
+ log_develop(gc, promotion)("Promoted " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes",
_numObjectsPromoted, _numWordsPromoted*sizeof(HeapWord));
- }
_numObjectsPromoted = 0;
_numWordsPromoted = 0;
)
- if (PrintGC && Verbose) {
// Call down the chain in contiguous_available needs the freelistLock
// so print this out before releasing the freeListLock.
- gclog_or_tty->print(" Contiguous available " SIZE_FORMAT " bytes ",
- contiguous_available());
- }
+ log_develop(gc)(" Contiguous available " SIZE_FORMAT " bytes ", contiguous_available());
}
#ifndef PRODUCT
bool CMSCollector::have_cms_token() {
Thread* thr = Thread::current();
@@ -2240,44 +2149,10 @@
}
return false;
}
#endif
-// Check reachability of the given heap address in CMS generation,
-// treating all other generations as roots.
-bool CMSCollector::is_cms_reachable(HeapWord* addr) {
- // We could "guarantee" below, rather than assert, but I'll
- // leave these as "asserts" so that an adventurous debugger
- // could try this in the product build provided some subset of
- // the conditions were met, provided they were interested in the
- // results and knew that the computation below wouldn't interfere
- // with other concurrent computations mutating the structures
- // being read or written.
- assert(SafepointSynchronize::is_at_safepoint(),
- "Else mutations in object graph will make answer suspect");
- assert(have_cms_token(), "Should hold cms token");
- assert(haveFreelistLocks(), "must hold free list locks");
- assert_lock_strong(bitMapLock());
-
- // Clear the marking bit map array before starting, but, just
- // for kicks, first report if the given address is already marked
- gclog_or_tty->print_cr("Start: Address " PTR_FORMAT " is%s marked", p2i(addr),
- _markBitMap.isMarked(addr) ? "" : " not");
-
- if (verify_after_remark()) {
- MutexLockerEx x(verification_mark_bm()->lock(), Mutex::_no_safepoint_check_flag);
- bool result = verification_mark_bm()->isMarked(addr);
- gclog_or_tty->print_cr("TransitiveMark: Address " PTR_FORMAT " %s marked", p2i(addr),
- result ? "IS" : "is NOT");
- return result;
- } else {
- gclog_or_tty->print_cr("Could not compute result");
- return false;
- }
-}
-
-
void
CMSCollector::print_on_error(outputStream* st) {
CMSCollector* collector = ConcurrentMarkSweepGeneration::_collector;
if (collector != NULL) {
CMSBitMap* bitmap = &collector->_markBitMap;
@@ -2307,22 +2182,24 @@
VerifyMarkedClosure(CMSBitMap* bm): _marks(bm), _failed(false) {}
bool do_bit(size_t offset) {
HeapWord* addr = _marks->offsetToHeapWord(offset);
if (!_marks->isMarked(addr)) {
- oop(addr)->print_on(gclog_or_tty);
- gclog_or_tty->print_cr(" (" INTPTR_FORMAT " should have been marked)", p2i(addr));
+ LogHandle(gc, verify) log;
+ ResourceMark rm;
+ oop(addr)->print_on(log.info_stream());
+ log.info(" (" INTPTR_FORMAT " should have been marked)", p2i(addr));
_failed = true;
}
return true;
}
bool failed() { return _failed; }
};
-bool CMSCollector::verify_after_remark(bool silent) {
- if (!silent) gclog_or_tty->print(" [Verifying CMS Marking... ");
+bool CMSCollector::verify_after_remark() {
+ GCTraceTime(Info, gc, verify) tm("Verifying CMS Marking.");
MutexLockerEx ml(verification_mark_bm()->lock(), Mutex::_no_safepoint_check_flag);
static bool init = false;
assert(SafepointSynchronize::is_at_safepoint(),
"Else mutations in object graph will make answer suspect");
@@ -2381,11 +2258,10 @@
verify_after_remark_work_2();
} else {
warning("Unrecognized value " UINTX_FORMAT " for CMSRemarkVerifyVariant",
CMSRemarkVerifyVariant);
}
- if (!silent) gclog_or_tty->print(" done] ");
return true;
}
void CMSCollector::verify_after_remark_work_1() {
ResourceMark rm;
@@ -2433,12 +2309,14 @@
// verification_mark_bm() is also marked in markBitMap(); flag all
// errors by printing corresponding objects.
VerifyMarkedClosure vcl(markBitMap());
verification_mark_bm()->iterate(&vcl);
if (vcl.failed()) {
- gclog_or_tty->print("Verification failed");
- gch->print_on(gclog_or_tty);
+ LogHandle(gc, verify) log;
+ log.info("Verification failed");
+ ResourceMark rm;
+ gch->print_on(log.info_stream());
fatal("CMS: failed marking verification after remark");
}
}
class VerifyKlassOopsKlassClosure : public KlassClosure {
@@ -2727,14 +2605,11 @@
// remember why we expanded; this information is used
// by shouldConcurrentCollect() when making decisions on whether to start
// a new CMS cycle.
if (success) {
set_expansion_cause(cause);
- if (PrintGCDetails && Verbose) {
- gclog_or_tty->print_cr("Expanded CMS gen for %s",
- CMSExpansionCause::to_string(cause));
- }
+ log_trace(gc)("Expanded CMS gen for %s", CMSExpansionCause::to_string(cause));
}
}
HeapWord* ConcurrentMarkSweepGeneration::expand_and_par_lab_allocate(CMSParGCThreadState* ps, size_t word_sz) {
HeapWord* res = NULL;
@@ -2798,79 +2673,50 @@
}
void ConcurrentMarkSweepGeneration::shrink_free_list_by(size_t bytes) {
assert_locked_or_safepoint(Heap_lock);
assert_lock_strong(freelistLock());
- if (PrintGCDetails && Verbose) {
- warning("Shrinking of CMS not yet implemented");
- }
+ log_trace(gc)("Shrinking of CMS not yet implemented");
return;
}
// Simple ctor/dtor wrapper for accounting & timer chores around concurrent
// phases.
class CMSPhaseAccounting: public StackObj {
public:
CMSPhaseAccounting(CMSCollector *collector,
- const char *phase,
- bool print_cr = true);
+ const char *title);
~CMSPhaseAccounting();
private:
CMSCollector *_collector;
- const char *_phase;
- elapsedTimer _wallclock;
- bool _print_cr;
+ const char *_title;
+ GCTraceConcTime(Info, gc) _trace_time;
public:
// Not MT-safe; so do not pass around these StackObj's
// where they may be accessed by other threads.
jlong wallclock_millis() {
- assert(_wallclock.is_active(), "Wall clock should not stop");
- _wallclock.stop(); // to record time
- jlong ret = _wallclock.milliseconds();
- _wallclock.start(); // restart
- return ret;
+ return TimeHelper::counter_to_millis(os::elapsed_counter() - _trace_time.start_time());
}
};
CMSPhaseAccounting::CMSPhaseAccounting(CMSCollector *collector,
- const char *phase,
- bool print_cr) :
- _collector(collector), _phase(phase), _print_cr(print_cr) {
+ const char *title) :
+ _collector(collector), _title(title), _trace_time(title) {
- if (PrintCMSStatistics != 0) {
_collector->resetYields();
- }
- if (PrintGCDetails) {
- gclog_or_tty->gclog_stamp();
- gclog_or_tty->print_cr("[%s-concurrent-%s-start]",
- _collector->cmsGen()->short_name(), _phase);
- }
_collector->resetTimer();
- _wallclock.start();
_collector->startTimer();
}
CMSPhaseAccounting::~CMSPhaseAccounting() {
- assert(_wallclock.is_active(), "Wall clock should not have stopped");
_collector->stopTimer();
- _wallclock.stop();
- if (PrintGCDetails) {
- gclog_or_tty->gclog_stamp();
- gclog_or_tty->print("[%s-concurrent-%s: %3.3f/%3.3f secs]",
- _collector->cmsGen()->short_name(),
- _phase, _collector->timerValue(), _wallclock.seconds());
- if (_print_cr) {
- gclog_or_tty->cr();
- }
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(" (CMS-concurrent-%s yielded %d times)", _phase,
- _collector->yields());
- }
- }
+ jlong end_counter = os::elapsed_counter();
+ log_debug(gc)("Concurrent active time: %.3fms", _collector->timerValue());
+ log_debug(gc, stats)(" (CMS %s yielded %d times)", _title, _collector->yields());
}
// CMS work
// The common parts of CMSParInitialMarkTask and CMSParRemarkTask.
@@ -2933,12 +2779,11 @@
// Setup the verification and class unloading state for this
// CMS collection cycle.
setup_cms_unloading_and_verification_state();
- NOT_PRODUCT(GCTraceTime t("\ncheckpointRootsInitialWork",
- PrintGCDetails && Verbose, true, _gc_timer_cm);)
+ GCTraceTime(Trace, gc) ts("checkpointRootsInitialWork", _gc_timer_cm);
// Reset all the PLAB chunk arrays if necessary.
if (_survivor_plab_array != NULL && !CMSPLABRecordAlways) {
reset_survivor_plab_arrays();
}
@@ -2965,13 +2810,11 @@
// Whenever a CLD is found, it will be claimed before proceeding to mark
// the klasses. The claimed marks need to be cleared before marking starts.
ClassLoaderDataGraph::clear_claimed_marks();
- if (CMSPrintEdenSurvivorChunks) {
print_eden_and_survivor_chunk_arrays();
- }
{
#if defined(COMPILER2) || INCLUDE_JVMCI
DerivedPointerTableDeactivate dpt_deact;
#endif
@@ -3038,21 +2881,19 @@
// Weak ref discovery note: We may be discovering weak
// refs in this generation concurrent (but interleaved) with
// weak ref discovery by the young generation collector.
CMSTokenSyncWithLocks ts(true, bitMapLock());
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- CMSPhaseAccounting pa(this, "mark", !PrintGCDetails);
+ GCTraceCPUTime tcpu;
+ CMSPhaseAccounting pa(this, "Concrurrent Mark");
bool res = markFromRootsWork();
if (res) {
_collectorState = Precleaning;
} else { // We failed and a foreground collection wants to take over
assert(_foregroundGCIsActive, "internal state inconsistency");
assert(_restart_addr == NULL, "foreground will restart from scratch");
- if (PrintGCDetails) {
- gclog_or_tty->print_cr("bailing out to foreground collection");
- }
+ log_debug(gc)("bailing out to foreground collection");
}
verify_overflow_empty();
return res;
}
@@ -3253,26 +3094,18 @@
assert(work_queue(worker_id)->size() == 0, "Expected to be empty");
// Scan the bitmap covering _cms_space, tracing through grey objects.
_timer.start();
do_scan_and_mark(worker_id, _cms_space);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("Finished cms space scanning in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- // XXX: need xxx/xxx type of notation, two timers
- }
+ log_debug(gc, stats)("Finished cms space scanning in %dth thread: %3.3f sec", worker_id, _timer.seconds());
// ... do work stealing
_timer.reset();
_timer.start();
do_work_steal(worker_id);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("Finished work stealing in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- // XXX: need xxx/xxx type of notation, two timers
- }
+ log_debug(gc, stats)("Finished work stealing in %dth thread: %3.3f sec", worker_id, _timer.seconds());
assert(_collector->_markStack.isEmpty(), "Should have been emptied");
assert(work_queue(worker_id)->size() == 0, "Should have been emptied");
// Note that under the current task protocol, the
// following assertion is true even of the spaces
// expanded since the completion of the concurrent
@@ -3483,14 +3316,11 @@
}
)
if (simulate_overflow ||
!(_work_queue->push(obj) || _overflow_stack->par_push(obj))) {
// stack overflow
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("CMS marking stack overflow (benign) at "
- SIZE_FORMAT, _overflow_stack->capacity());
- }
+ log_debug(gc, stats)("CMS marking stack overflow (benign) at " SIZE_FORMAT, _overflow_stack->capacity());
// We cannot assert that the overflow stack is full because
// it may have been emptied since.
assert(simulate_overflow ||
_work_queue->size() == _work_queue->max_elems(),
"Else push should have succeeded");
@@ -3571,13 +3401,11 @@
// serve our purpose. XXX
assert_lock_strong(_bit_map_lock);
_bit_map_lock->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// It is possible for whichever thread initiated the yield request
// not to get a chance to wake up and take the bitmap lock between
// this thread releasing it and reacquiring it. So, while the
// should_yield() flag is on, let's sleep for a bit to give the
@@ -3735,12 +3563,12 @@
* CMSScheduleRemarkEdenPenetration)) {
_start_sampling = true;
} else {
_start_sampling = false;
}
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- CMSPhaseAccounting pa(this, "preclean", !PrintGCDetails);
+ GCTraceCPUTime tcpu;
+ CMSPhaseAccounting pa(this, "Concurrent Preclean");
preclean_work(CMSPrecleanRefLists1, CMSPrecleanSurvivors1);
}
CMSTokenSync x(true); // is cms thread
if (CMSPrecleaningEnabled) {
sample_eden();
@@ -3764,12 +3592,12 @@
// past the next scavenge in an effort to
// schedule the pause as described above. By choosing
// CMSScheduleRemarkEdenSizeThreshold >= max eden size
// we will never do an actual abortable preclean cycle.
if (get_eden_used() > CMSScheduleRemarkEdenSizeThreshold) {
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- CMSPhaseAccounting pa(this, "abortable-preclean", !PrintGCDetails);
+ GCTraceCPUTime tcpu;
+ CMSPhaseAccounting pa(this, "Concurrent Abortable Preclean");
// We need more smarts in the abortable preclean
// loop below to deal with cases where allocation
// in young gen is very very slow, and our precleaning
// is running a losing race against a horde of
// mutators intent on flooding us with CMS updates
@@ -3787,19 +3615,15 @@
loops++;
// Voluntarily terminate abortable preclean phase if we have
// been at it for too long.
if ((CMSMaxAbortablePrecleanLoops != 0) &&
loops >= CMSMaxAbortablePrecleanLoops) {
- if (PrintGCDetails) {
- gclog_or_tty->print(" CMS: abort preclean due to loops ");
- }
+ log_debug(gc)(" CMS: abort preclean due to loops ");
break;
}
if (pa.wallclock_millis() > CMSMaxAbortablePrecleanTime) {
- if (PrintGCDetails) {
- gclog_or_tty->print(" CMS: abort preclean due to time ");
- }
+ log_debug(gc)(" CMS: abort preclean due to time ");
break;
}
// If we are doing little work each iteration, we should
// take a short break.
if (workdone < CMSAbortablePrecleanMinWorkPerIteration) {
@@ -3808,15 +3632,13 @@
cmsThread()->wait_on_cms_lock(CMSAbortablePrecleanWaitMillis);
startTimer();
waited++;
}
}
- if (PrintCMSStatistics > 0) {
- gclog_or_tty->print(" [" SIZE_FORMAT " iterations, " SIZE_FORMAT " waits, " SIZE_FORMAT " cards)] ",
+ log_debug(gc, stats)(" [" SIZE_FORMAT " iterations, " SIZE_FORMAT " waits, " SIZE_FORMAT " cards)] ",
loops, waited, cumworkdone);
}
- }
CMSTokenSync x(true); // is cms thread
if (_collectorState != Idling) {
assert(_collectorState == AbortablePreclean,
"Spontaneous state transition?");
_collectorState = FinalMarking;
@@ -3955,13 +3777,11 @@
size_t numIter, cumNumCards, lastNumCards, curNumCards;
for (numIter = 0, cumNumCards = lastNumCards = curNumCards = 0;
numIter < CMSPrecleanIter;
numIter++, lastNumCards = curNumCards, cumNumCards += curNumCards) {
curNumCards = preclean_mod_union_table(_cmsGen, &smoac_cl);
- if (Verbose && PrintGCDetails) {
- gclog_or_tty->print(" (modUnionTable: " SIZE_FORMAT " cards)", curNumCards);
- }
+ log_trace(gc)(" (modUnionTable: " SIZE_FORMAT " cards)", curNumCards);
// Either there are very few dirty cards, so re-mark
// pause will be small anyway, or our pre-cleaning isn't
// that much faster than the rate at which cards are being
// dirtied, so we might as well stop and re-mark since
// precleaning won't improve our re-mark time by much.
@@ -3977,14 +3797,12 @@
preclean_klasses(&mrias_cl, _cmsGen->freelistLock());
curNumCards = preclean_card_table(_cmsGen, &smoac_cl);
cumNumCards += curNumCards;
- if (PrintGCDetails && PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(" (cardTable: " SIZE_FORMAT " cards, re-scanned " SIZE_FORMAT " cards, " SIZE_FORMAT " iterations)",
+ log_debug(gc, stats)(" (cardTable: " SIZE_FORMAT " cards, re-scanned " SIZE_FORMAT " cards, " SIZE_FORMAT " iterations)",
curNumCards, cumNumCards, numIter);
- }
return cumNumCards; // as a measure of useful work done
}
// PRECLEANING NOTES:
// Precleaning involves:
@@ -4234,23 +4052,21 @@
TraceCMSMemoryManagerStats tms(_collectorState,GenCollectedHeap::heap()->gc_cause());
verify_work_stacks_empty();
verify_overflow_empty();
- if (PrintGCDetails) {
- gclog_or_tty->print("[YG occupancy: " SIZE_FORMAT " K (" SIZE_FORMAT " K)]",
- _young_gen->used() / K,
- _young_gen->capacity() / K);
- }
+ log_debug(gc)("YG occupancy: " SIZE_FORMAT " K (" SIZE_FORMAT " K)",
+ _young_gen->used() / K, _young_gen->capacity() / K);
{
if (CMSScavengeBeforeRemark) {
GenCollectedHeap* gch = GenCollectedHeap::heap();
// Temporarily set flag to false, GCH->do_collection will
// expect it to be false and set to true
FlagSetting fl(gch->_is_gc_active, false);
- NOT_PRODUCT(GCTraceTime t("Scavenge-Before-Remark",
- PrintGCDetails && Verbose, true, _gc_timer_cm);)
+
+ GCTraceTime(Trace, gc) tm("Scavenge Before Remark", _gc_timer_cm);
+
gch->do_collection(true, // full (i.e. force, see below)
false, // !clear_all_soft_refs
0, // size
false, // is_tlab
GenCollectedHeap::YoungGen // type
@@ -4264,11 +4080,11 @@
verify_work_stacks_empty();
verify_overflow_empty();
}
void CMSCollector::checkpointRootsFinalWork() {
- NOT_PRODUCT(GCTraceTime tr("checkpointRootsFinalWork", PrintGCDetails, false, _gc_timer_cm);)
+ GCTraceTime(Trace, gc) tm("checkpointRootsFinalWork", _gc_timer_cm);
assert(haveFreelistLocks(), "must have free list locks");
assert_lock_strong(bitMapLock());
ResourceMark rm;
@@ -4296,13 +4112,11 @@
// so here just in case a scavenge did not happen.
gch->ensure_parsability(false); // fill TLAB's, but no need to retire them
// Update the saved marks which may affect the root scans.
gch->save_marks();
- if (CMSPrintEdenSurvivorChunks) {
print_eden_and_survivor_chunk_arrays();
- }
{
#if defined(COMPILER2) || INCLUDE_JVMCI
DerivedPointerTableDeactivate dpt_deact;
#endif
@@ -4316,22 +4130,22 @@
// are detected via the mod union table which is the set of all cards
// dirtied since the first checkpoint in this GC cycle and prior to
// the most recent young generation GC, minus those cleaned up by the
// concurrent precleaning.
if (CMSParallelRemarkEnabled) {
- GCTraceTime t("Rescan (parallel) ", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Debug, gc) t("Rescan (parallel)", _gc_timer_cm);
do_remark_parallel();
} else {
- GCTraceTime t("Rescan (non-parallel) ", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Debug, gc) t("Rescan (non-parallel)", _gc_timer_cm);
do_remark_non_parallel();
}
}
verify_work_stacks_empty();
verify_overflow_empty();
{
- NOT_PRODUCT(GCTraceTime ts("refProcessingWork", PrintGCDetails, false, _gc_timer_cm);)
+ GCTraceTime(Trace, gc) ts("refProcessingWork", _gc_timer_cm);
refProcessingWork();
}
verify_work_stacks_empty();
verify_overflow_empty();
@@ -4346,43 +4160,31 @@
// recurrence of that condition.
assert(_markStack.isEmpty(), "No grey objects");
size_t ser_ovflw = _ser_pmc_remark_ovflw + _ser_pmc_preclean_ovflw +
_ser_kac_ovflw + _ser_kac_preclean_ovflw;
if (ser_ovflw > 0) {
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("Marking stack overflow (benign) "
- "(pmc_pc=" SIZE_FORMAT ", pmc_rm=" SIZE_FORMAT ", kac=" SIZE_FORMAT
- ", kac_preclean=" SIZE_FORMAT ")",
- _ser_pmc_preclean_ovflw, _ser_pmc_remark_ovflw,
- _ser_kac_ovflw, _ser_kac_preclean_ovflw);
- }
+ log_debug(gc, stats)("Marking stack overflow (benign) (pmc_pc=" SIZE_FORMAT ", pmc_rm=" SIZE_FORMAT ", kac=" SIZE_FORMAT ", kac_preclean=" SIZE_FORMAT ")",
+ _ser_pmc_preclean_ovflw, _ser_pmc_remark_ovflw, _ser_kac_ovflw, _ser_kac_preclean_ovflw);
_markStack.expand();
_ser_pmc_remark_ovflw = 0;
_ser_pmc_preclean_ovflw = 0;
_ser_kac_preclean_ovflw = 0;
_ser_kac_ovflw = 0;
}
if (_par_pmc_remark_ovflw > 0 || _par_kac_ovflw > 0) {
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("Work queue overflow (benign) "
- "(pmc_rm=" SIZE_FORMAT ", kac=" SIZE_FORMAT ")",
+ log_debug(gc, stats)("Work queue overflow (benign) (pmc_rm=" SIZE_FORMAT ", kac=" SIZE_FORMAT ")",
_par_pmc_remark_ovflw, _par_kac_ovflw);
- }
_par_pmc_remark_ovflw = 0;
_par_kac_ovflw = 0;
}
- if (PrintCMSStatistics != 0) {
if (_markStack._hit_limit > 0) {
- gclog_or_tty->print_cr(" (benign) Hit max stack size limit (" SIZE_FORMAT ")",
+ log_debug(gc, stats)(" (benign) Hit max stack size limit (" SIZE_FORMAT ")",
_markStack._hit_limit);
}
if (_markStack._failed_double > 0) {
- gclog_or_tty->print_cr(" (benign) Failed stack doubling (" SIZE_FORMAT "),"
- " current capacity " SIZE_FORMAT,
- _markStack._failed_double,
- _markStack.capacity());
- }
+ log_debug(gc, stats)(" (benign) Failed stack doubling (" SIZE_FORMAT "), current capacity " SIZE_FORMAT,
+ _markStack._failed_double, _markStack.capacity());
}
_markStack._hit_limit = 0;
_markStack._failed_double = 0;
if ((VerifyAfterGC || VerifyDuringGC) &&
@@ -4413,15 +4215,11 @@
// ---------- young gen roots --------------
{
work_on_young_gen_roots(worker_id, &par_mri_cl);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished young gen initial mark scan work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished young gen initial mark scan work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
}
// ---------- remaining roots --------------
_timer.reset();
_timer.start();
@@ -4438,15 +4236,11 @@
&cld_closure);
assert(_collector->should_unload_classes()
|| (_collector->CMSCollector::roots_scanning_options() & GenCollectedHeap::SO_AllCodeCache),
"if we didn't scan the code cache, we have to be ready to drop nmethods with expired weak oops");
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished remaining root initial mark scan work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished remaining root initial mark scan work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
}
// Parallel remark task
class CMSParRemarkTask: public CMSParMarkTask {
CompactibleFreeListSpace* _cms_space;
@@ -4555,15 +4349,11 @@
// work first.
// ---------- young gen roots --------------
{
work_on_young_gen_roots(worker_id, &par_mrias_cl);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished young gen rescan work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished young gen rescan work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
}
// ---------- remaining roots --------------
_timer.reset();
_timer.start();
@@ -4578,15 +4368,11 @@
assert(_collector->should_unload_classes()
|| (_collector->CMSCollector::roots_scanning_options() & GenCollectedHeap::SO_AllCodeCache),
"if we didn't scan the code cache, we have to be ready to drop nmethods with expired weak oops");
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished remaining root rescan work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished remaining root rescan work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
// ---------- unhandled CLD scanning ----------
if (worker_id == 0) { // Single threaded at the moment.
_timer.reset();
_timer.start();
@@ -4601,15 +4387,11 @@
// We don't need to keep track of new CLDs anymore.
ClassLoaderDataGraph::remember_new_clds(false);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished unhandled CLD scanning work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished unhandled CLD scanning work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
}
// ---------- dirty klass scanning ----------
if (worker_id == 0) { // Single threaded at the moment.
_timer.reset();
@@ -4618,15 +4400,11 @@
// Scan all classes that was dirtied during the concurrent marking phase.
RemarkKlassClosure remark_klass_closure(&par_mrias_cl);
ClassLoaderDataGraph::classes_do(&remark_klass_closure);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished dirty klass scanning work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished dirty klass scanning work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
}
// We might have added oops to ClassLoaderData::_handles during the
// concurrent marking phase. These oops point to newly allocated objects
// that are guaranteed to be kept alive. Either by the direct allocation
@@ -4640,27 +4418,19 @@
// Do the rescan tasks for each of the two spaces
// (cms_space) in turn.
// "worker_id" is passed to select the task_queue for "worker_id"
do_dirty_card_rescan_tasks(_cms_space, worker_id, &par_mrias_cl);
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished dirty card rescan work in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished dirty card rescan work in %dth thread: %3.3f sec", worker_id, _timer.seconds());
// ---------- steal work from other threads ...
// ---------- ... and drain overflow list.
_timer.reset();
_timer.start();
do_work_steal(worker_id, &par_mrias_cl, _collector->hash_seed(worker_id));
_timer.stop();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr(
- "Finished work stealing in %dth thread: %3.3f sec",
- worker_id, _timer.seconds());
- }
+ log_debug(gc, stats)("Finished work stealing in %dth thread: %3.3f sec", worker_id, _timer.seconds());
}
// Note that parameter "i" is not used.
void
CMSParMarkTask::do_young_space_rescan(uint worker_id,
@@ -4850,15 +4620,11 @@
// Loop around, finish this work, and try to steal some more
} else if (terminator()->offer_termination()) {
break; // nirvana from the infinite cycle
}
}
- NOT_PRODUCT(
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print("\n\t(%d: stole %d oops)", i, num_steals);
- }
- )
+ log_develop(gc, stats)("\t(%d: stole %d oops)", i, num_steals);
assert(work_q->size() == 0 && _collector->overflow_list_is_empty(),
"Else our work is not yet done");
}
// Record object boundaries in _eden_chunk_array by sampling the eden
@@ -4951,13 +4717,11 @@
_survivor_chunk_array[i] = min_val;
_cursor[min_tid]++;
}
// We are all done; record the size of the _survivor_chunk_array
_survivor_chunk_index = i; // exclusive: [0, i)
- if (PrintCMSStatistics > 0) {
- gclog_or_tty->print(" (Survivor:" SIZE_FORMAT "chunks) ", i);
- }
+ log_debug(gc, stats)(" (Survivor:" SIZE_FORMAT "chunks) ", i);
// Verify that we used up all the recorded entries
#ifdef ASSERT
size_t total = 0;
for (int j = 0; j < no_of_gc_threads; j++) {
assert(_cursor[j] == _survivor_plab_array[j].end(), "Ctl pt invariant");
@@ -4965,14 +4729,12 @@
}
assert(total == _survivor_chunk_index, "Ctl Pt Invariant");
// Check that the merged array is in sorted order
if (total > 0) {
for (size_t i = 0; i < total - 1; i++) {
- if (PrintCMSStatistics > 0) {
- gclog_or_tty->print(" (chunk" SIZE_FORMAT ":" INTPTR_FORMAT ") ",
+ log_develop(gc, stats)(" (chunk" SIZE_FORMAT ":" INTPTR_FORMAT ") ",
i, p2i(_survivor_chunk_array[i]));
- }
assert(_survivor_chunk_array[i] < _survivor_chunk_array[i+1],
"Not sorted");
}
}
#endif // ASSERT
@@ -5102,11 +4864,11 @@
MarkFromDirtyCardsClosure
markFromDirtyCardsClosure(this, _span,
NULL, // space is set further below
&_markBitMap, &_markStack, &mrias_cl);
{
- GCTraceTime t("grey object rescan", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Trace, gc) t("Grey Object Rescan", _gc_timer_cm);
// Iterate over the dirty cards, setting the corresponding bits in the
// mod union table.
{
ModUnionClosure modUnionClosure(&_modUnionTable);
_ct->ct_bs()->dirty_card_iterate(
@@ -5127,23 +4889,20 @@
HeapWord* ub = (HeapWord*)round_to((intptr_t)ur.end(), alignment);
MemRegion cms_span(lb, ub);
_modUnionTable.dirty_range_iterate_clear(cms_span,
&markFromDirtyCardsClosure);
verify_work_stacks_empty();
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print(" (re-scanned " SIZE_FORMAT " dirty cards in cms gen) ",
- markFromDirtyCardsClosure.num_dirty_cards());
- }
+ log_debug(gc, stats)(" (re-scanned " SIZE_FORMAT " dirty cards in cms gen) ", markFromDirtyCardsClosure.num_dirty_cards());
}
}
if (VerifyDuringGC &&
GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
Universe::verify();
}
{
- GCTraceTime t("root rescan", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Trace, gc) t("Root Rescan", _gc_timer_cm);
verify_work_stacks_empty();
gch->rem_set()->prepare_for_younger_refs_iterate(false); // Not parallel.
StrongRootsScope srs(1);
@@ -5161,11 +4920,11 @@
|| (roots_scanning_options() & GenCollectedHeap::SO_AllCodeCache),
"if we didn't scan the code cache, we have to be ready to drop nmethods with expired weak oops");
}
{
- GCTraceTime t("visit unhandled CLDs", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Trace, gc) t("Visit Unhandled CLDs", _gc_timer_cm);
verify_work_stacks_empty();
// Scan all class loader data objects that might have been introduced
// during concurrent marking.
@@ -5180,11 +4939,11 @@
verify_work_stacks_empty();
}
{
- GCTraceTime t("dirty klass scan", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Trace, gc) t("Dirty Klass Scan", _gc_timer_cm);
verify_work_stacks_empty();
RemarkKlassClosure remark_klass_closure(&mrias_cl);
ClassLoaderDataGraph::classes_do(&remark_klass_closure);
@@ -5342,15 +5101,11 @@
// Loop around, finish this work, and try to steal some more
} else if (terminator()->offer_termination()) {
break; // nirvana from the infinite cycle
}
}
- NOT_PRODUCT(
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print("\n\t(%d: stole %d oops)", i, num_steals);
- }
- )
+ log_develop(gc, stats)("\t(%d: stole %d oops)", i, num_steals);
}
void CMSRefProcTaskExecutor::execute(ProcessTask& task)
{
GenCollectedHeap* gch = GenCollectedHeap::heap();
@@ -5388,11 +5143,11 @@
&_markStack, false /* !preclean */);
CMSDrainMarkingStackClosure cmsDrainMarkingStackClosure(this,
_span, &_markBitMap, &_markStack,
&cmsKeepAliveClosure, false /* !preclean */);
{
- GCTraceTime t("weak refs processing", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Debug, gc) t("Weak Refs Processing", _gc_timer_cm);
ReferenceProcessorStats stats;
if (rp->processing_is_mt()) {
// Set the degree of MT here. If the discovery is done MT, there
// may have been a different number of threads doing the discovery
@@ -5430,11 +5185,11 @@
// This is the point where the entire marking should have completed.
verify_work_stacks_empty();
if (should_unload_classes()) {
{
- GCTraceTime t("class unloading", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Debug, gc) t("Class Unloading", _gc_timer_cm);
// Unload classes and purge the SystemDictionary.
bool purged_class = SystemDictionary::do_unloading(&_is_alive_closure);
// Unload nmethods.
@@ -5443,17 +5198,17 @@
// Prune dead klasses from subklass/sibling/implementor lists.
Klass::clean_weak_klass_links(&_is_alive_closure);
}
{
- GCTraceTime t("scrub symbol table", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Debug, gc) t("Scrub Symbol Table", _gc_timer_cm);
// Clean up unreferenced symbols in symbol table.
SymbolTable::unlink();
}
{
- GCTraceTime t("scrub string table", PrintGCDetails, false, _gc_timer_cm);
+ GCTraceTime(Debug, gc) t("Scrub String Table", _gc_timer_cm);
// Delete entries for dead interned strings.
StringTable::unlink(&_is_alive_closure);
}
}
@@ -5516,12 +5271,12 @@
assert(!_intra_sweep_timer.is_active(), "Should not be active");
_intra_sweep_timer.reset();
_intra_sweep_timer.start();
{
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- CMSPhaseAccounting pa(this, "sweep", !PrintGCDetails);
+ GCTraceCPUTime tcpu;
+ CMSPhaseAccounting pa(this, "Concurrent Sweep");
// First sweep the old gen
{
CMSTokenSyncWithLocks ts(true, _cmsGen->freelistLock(),
bitMapLock());
sweepWork(_cmsGen);
@@ -5600,17 +5355,12 @@
largestAddr = _cmsSpace->end();
}
size_t largestOffset = pointer_delta(largestAddr, minAddr);
size_t nearLargestOffset =
(size_t)((double)largestOffset * nearLargestPercent) - MinChunkSize;
- if (PrintFLSStatistics != 0) {
- gclog_or_tty->print_cr(
- "CMS: Large Block: " PTR_FORMAT ";"
- " Proximity: " PTR_FORMAT " -> " PTR_FORMAT,
- p2i(largestAddr),
- p2i(_cmsSpace->nearLargestChunk()), p2i(minAddr + nearLargestOffset));
- }
+ log_debug(gc, freelist, stats)("CMS: Large Block: " PTR_FORMAT "; Proximity: " PTR_FORMAT " -> " PTR_FORMAT,
+ p2i(largestAddr), p2i(_cmsSpace->nearLargestChunk()), p2i(minAddr + nearLargestOffset));
_cmsSpace->set_nearLargestChunk(minAddr + nearLargestOffset);
}
bool ConcurrentMarkSweepGeneration::isNearLargestChunk(HeapWord* addr) {
return addr >= _cmsSpace->nearLargestChunk();
@@ -5700,12 +5450,12 @@
return;
}
// Clear the mark bitmap (no grey objects to start with)
// for the next cycle.
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- CMSPhaseAccounting cmspa(this, "reset", !PrintGCDetails);
+ GCTraceCPUTime tcpu;
+ CMSPhaseAccounting cmspa(this, "Concurrent Reset");
HeapWord* curAddr = _markBitMap.startWord();
while (curAddr < _markBitMap.endWord()) {
size_t remaining = pointer_delta(_markBitMap.endWord(), curAddr);
MemRegion chunk(curAddr, MIN2(CMSBitMapYieldQuantum, remaining));
@@ -5717,13 +5467,11 @@
"CMS thread should hold CMS token");
assert_lock_strong(bitMapLock());
bitMapLock()->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
stopTimer();
- if (PrintCMSStatistics != 0) {
incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0; i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
!CMSCollector::foregroundGCIsActive(); ++i) {
@@ -5756,29 +5504,24 @@
_collectorState = Idling;
register_gc_end();
}
void CMSCollector::do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause) {
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- GCTraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, NULL);
+ GCTraceCPUTime tcpu;
TraceCollectorStats tcs(counters());
switch (op) {
case CMS_op_checkpointRootsInitial: {
+ GCTraceTime(Info, gc) t("Pause Initial Mark", NULL, GCCause::_no_gc, true);
SvcGCMarker sgcm(SvcGCMarker::OTHER);
checkpointRootsInitial();
- if (PrintGC) {
- _cmsGen->printOccupancy("initial-mark");
- }
break;
}
case CMS_op_checkpointRootsFinal: {
+ GCTraceTime(Info, gc) t("Pause Remark", NULL, GCCause::_no_gc, true);
SvcGCMarker sgcm(SvcGCMarker::OTHER);
checkpointRootsFinal();
- if (PrintGC) {
- _cmsGen->printOccupancy("remark");
- }
break;
}
default:
fatal("No such CMS_op");
}
@@ -5987,13 +5730,13 @@
// For now we take the expedient path of just disabling the
// messages for the problematic case.)
void CMSMarkStack::expand() {
assert(_capacity <= MarkStackSizeMax, "stack bigger than permitted");
if (_capacity == MarkStackSizeMax) {
- if (_hit_limit++ == 0 && !CMSConcurrentMTEnabled && PrintGCDetails) {
+ if (_hit_limit++ == 0 && !CMSConcurrentMTEnabled) {
// We print a warning message only once per CMS cycle.
- gclog_or_tty->print_cr(" (benign) Hit CMSMarkStack max size limit");
+ log_debug(gc)(" (benign) Hit CMSMarkStack max size limit");
}
return;
}
// Double capacity if possible
size_t new_capacity = MIN2(_capacity*2, MarkStackSizeMax);
@@ -6009,15 +5752,14 @@
fatal("Not enough swap for expanded marking stack");
}
_base = (oop*)(_virtual_space.low());
_index = 0;
_capacity = new_capacity;
- } else if (_failed_double++ == 0 && !CMSConcurrentMTEnabled && PrintGCDetails) {
+ } else if (_failed_double++ == 0 && !CMSConcurrentMTEnabled) {
// Failed to double capacity, continue;
// we print a detail message only once per CMS cycle.
- gclog_or_tty->print(" (benign) Failed to expand marking stack from " SIZE_FORMAT "K to "
- SIZE_FORMAT "K",
+ log_debug(gc)(" (benign) Failed to expand marking stack from " SIZE_FORMAT "K to " SIZE_FORMAT "K",
_capacity / K, new_capacity / K);
}
}
@@ -6091,12 +5833,14 @@
assert(obj->is_oop(), "expected an oop");
HeapWord* addr = (HeapWord*)obj;
if (_span.contains(addr)) {
_verification_bm->mark(addr);
if (!_cms_bm->isMarked(addr)) {
- oop(addr)->print();
- gclog_or_tty->print_cr(" (" INTPTR_FORMAT " should have been marked)", p2i(addr));
+ LogHandle(gc, verify) log;
+ ResourceMark rm;
+ oop(addr)->print_on(log.info_stream());
+ log.info(" (" INTPTR_FORMAT " should have been marked)", p2i(addr));
fatal("... aborting");
}
}
}
@@ -6188,13 +5932,11 @@
// relinquish the free_list_lock and bitMaplock()
_bit_map->lock()->unlock();
_freelistLock->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0;
i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
@@ -6346,13 +6088,11 @@
// relinquish the free_list_lock and bitMaplock()
_bitMap->lock()->unlock();
_freelistLock->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0; i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
!CMSCollector::foregroundGCIsActive(); ++i) {
@@ -6415,13 +6155,11 @@
assert_lock_strong(_bit_map->lock());
// Relinquish the bit map lock
_bit_map->lock()->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0; i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
!CMSCollector::foregroundGCIsActive(); ++i) {
@@ -6570,13 +6308,11 @@
"CMS thread should hold CMS token");
assert_lock_strong(_bitMap->lock());
_bitMap->lock()->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0; i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
!CMSCollector::foregroundGCIsActive(); ++i) {
@@ -6878,21 +6614,19 @@
HeapWord* addr = (HeapWord*)obj;
if (_span.contains(addr) && !_verification_bm->isMarked(addr)) {
// Oop lies in _span and isn't yet grey or black
_verification_bm->mark(addr); // now grey
if (!_cms_bm->isMarked(addr)) {
- oop(addr)->print();
- gclog_or_tty->print_cr(" (" INTPTR_FORMAT " should have been marked)",
- p2i(addr));
+ LogHandle(gc, verify) log;
+ ResourceMark rm;
+ oop(addr)->print_on(log.info_stream());
+ log.info(" (" INTPTR_FORMAT " should have been marked)", p2i(addr));
fatal("... aborting");
}
if (!_mark_stack->push(obj)) { // stack overflow
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("CMS marking stack overflow (benign) at "
- SIZE_FORMAT, _mark_stack->capacity());
- }
+ log_debug(gc, stats)("CMS marking stack overflow (benign) at " SIZE_FORMAT, _mark_stack->capacity());
assert(_mark_stack->isFull(), "Else push should have succeeded");
handle_stack_overflow(addr);
}
// anything including and to the right of _finger
// will be scanned as we iterate over the remainder of the
@@ -6988,14 +6722,11 @@
// simulate a stack overflow
simulate_overflow = true;
}
)
if (simulate_overflow || !_markStack->push(obj)) { // stack overflow
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("CMS marking stack overflow (benign) at "
- SIZE_FORMAT, _markStack->capacity());
- }
+ log_debug(gc, stats)("CMS marking stack overflow (benign) at " SIZE_FORMAT, _markStack->capacity());
assert(simulate_overflow || _markStack->isFull(), "Else push should have succeeded");
handle_stack_overflow(addr);
}
}
// anything including and to the right of _finger
@@ -7040,14 +6771,11 @@
}
)
if (simulate_overflow ||
!(_work_queue->push(obj) || _overflow_stack->par_push(obj))) {
// stack overflow
- if (PrintCMSStatistics != 0) {
- gclog_or_tty->print_cr("CMS marking stack overflow (benign) at "
- SIZE_FORMAT, _overflow_stack->capacity());
- }
+ log_debug(gc, stats)("CMS marking stack overflow (benign) at " SIZE_FORMAT, _overflow_stack->capacity());
// We cannot assert that the overflow stack is full because
// it may have been emptied since.
assert(simulate_overflow ||
_work_queue->size() == _work_queue->max_elems(),
"Else push should have succeeded");
@@ -7205,13 +6933,11 @@
bml->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0; i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
!CMSCollector::foregroundGCIsActive(); ++i) {
@@ -7238,14 +6964,11 @@
// assert(mr.word_size()%CardTableModRefBS::card_size_in_words == 0,
// "mr should be a range of cards");
// However, that would be too strong in one case -- the last
// partition ends at _unallocated_block which, in general, can be
// an arbitrary boundary, not necessarily card aligned.
- if (PrintCMSStatistics != 0) {
- _num_dirty_cards +=
- mr.word_size()/CardTableModRefBS::card_size_in_words;
- }
+ _num_dirty_cards += mr.word_size()/CardTableModRefBS::card_size_in_words;
_space->object_iterate_mem(mr, &_scan_cl);
}
SweepClosure::SweepClosure(CMSCollector* collector,
ConcurrentMarkSweepGeneration* g,
@@ -7274,14 +6997,12 @@
_sp->initializeIndexedFreeListArrayReturnedBytes();
_sp->dictionary()->initialize_dict_returned_bytes();
)
assert(_limit >= _sp->bottom() && _limit <= _sp->end(),
"sweep _limit out of bounds");
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr("\n====================\nStarting new sweep with limit " PTR_FORMAT,
- p2i(_limit));
- }
+ log_develop(gc, sweep)("====================");
+ log_develop(gc, sweep)("Starting new sweep with limit " PTR_FORMAT, p2i(_limit));
}
void SweepClosure::print_on(outputStream* st) const {
tty->print_cr("_sp = [" PTR_FORMAT "," PTR_FORMAT ")",
p2i(_sp->bottom()), p2i(_sp->end()));
@@ -7304,46 +7025,36 @@
if (inFreeRange()) {
warning("inFreeRange() should have been reset; dumping state of SweepClosure");
print();
ShouldNotReachHere();
}
- if (Verbose && PrintGC) {
- gclog_or_tty->print("Collected " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes",
+
+ if (log_is_enabled(Debug, gc, sweep)) {
+ log_debug(gc, sweep)("Collected " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes",
_numObjectsFreed, _numWordsFreed*sizeof(HeapWord));
- gclog_or_tty->print_cr("\nLive " SIZE_FORMAT " objects, "
- SIZE_FORMAT " bytes "
- "Already free " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes",
- _numObjectsLive, _numWordsLive*sizeof(HeapWord),
- _numObjectsAlreadyFree, _numWordsAlreadyFree*sizeof(HeapWord));
- size_t totalBytes = (_numWordsFreed + _numWordsLive + _numWordsAlreadyFree)
- * sizeof(HeapWord);
- gclog_or_tty->print_cr("Total sweep: " SIZE_FORMAT " bytes", totalBytes);
+ log_debug(gc, sweep)("Live " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes Already free " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes",
+ _numObjectsLive, _numWordsLive*sizeof(HeapWord), _numObjectsAlreadyFree, _numWordsAlreadyFree*sizeof(HeapWord));
+ size_t totalBytes = (_numWordsFreed + _numWordsLive + _numWordsAlreadyFree) * sizeof(HeapWord);
+ log_debug(gc, sweep)("Total sweep: " SIZE_FORMAT " bytes", totalBytes);
+ }
- if (PrintCMSStatistics && CMSVerifyReturnedBytes) {
+ if (log_is_enabled(Debug, gc, stats) && CMSVerifyReturnedBytes) {
size_t indexListReturnedBytes = _sp->sumIndexedFreeListArrayReturnedBytes();
size_t dict_returned_bytes = _sp->dictionary()->sum_dict_returned_bytes();
size_t returned_bytes = indexListReturnedBytes + dict_returned_bytes;
- gclog_or_tty->print("Returned " SIZE_FORMAT " bytes", returned_bytes);
- gclog_or_tty->print(" Indexed List Returned " SIZE_FORMAT " bytes",
- indexListReturnedBytes);
- gclog_or_tty->print_cr(" Dictionary Returned " SIZE_FORMAT " bytes",
- dict_returned_bytes);
- }
- }
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr("end of sweep with _limit = " PTR_FORMAT "\n================",
- p2i(_limit));
+ log_debug(gc, stats)("Returned " SIZE_FORMAT " bytes Indexed List Returned " SIZE_FORMAT " bytes Dictionary Returned " SIZE_FORMAT " bytes",
+ returned_bytes, indexListReturnedBytes, dict_returned_bytes);
}
+ log_develop(gc, sweep)("end of sweep with _limit = " PTR_FORMAT, p2i(_limit));
+ log_develop(gc, sweep)("================");
}
#endif // PRODUCT
void SweepClosure::initialize_free_range(HeapWord* freeFinger,
bool freeRangeInFreeLists) {
- if (CMSTraceSweeper) {
- gclog_or_tty->print("---- Start free range at " PTR_FORMAT " with free block (%d)\n",
+ log_develop(gc, sweep)("---- Start free range at " PTR_FORMAT " with free block (%d)",
p2i(freeFinger), freeRangeInFreeLists);
- }
assert(!inFreeRange(), "Trampling existing free range");
set_inFreeRange(true);
set_lastFreeRangeCoalesced(false);
set_freeFinger(freeFinger);
@@ -7405,18 +7116,14 @@
if (inFreeRange()) {
assert(freeFinger() >= _sp->bottom() && freeFinger() < _limit,
"freeFinger() " PTR_FORMAT " is out-of-bounds", p2i(freeFinger()));
flush_cur_free_chunk(freeFinger(),
pointer_delta(addr, freeFinger()));
- if (CMSTraceSweeper) {
- gclog_or_tty->print("Sweep: last chunk: ");
- gclog_or_tty->print("put_free_blk " PTR_FORMAT " (" SIZE_FORMAT ") "
- "[coalesced:%d]\n",
+ log_develop(gc, sweep)("Sweep: last chunk: put_free_blk " PTR_FORMAT " (" SIZE_FORMAT ") [coalesced:%d]",
p2i(freeFinger()), pointer_delta(addr, freeFinger()),
lastFreeRangeCoalesced() ? 1 : 0);
}
- }
// help the iterator loop finish
return pointer_delta(_sp->end(), addr);
}
@@ -7622,13 +7329,11 @@
assert((HeapWord*)fc <= _limit, "sweep invariant");
if (CMSTestInFreeList && fcInFreeLists) {
assert(_sp->verify_chunk_in_free_list(fc), "free chunk is not in free lists");
}
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr(" -- pick up another chunk at " PTR_FORMAT " (" SIZE_FORMAT ")", p2i(fc), chunkSize);
- }
+ log_develop(gc, sweep)(" -- pick up another chunk at " PTR_FORMAT " (" SIZE_FORMAT ")", p2i(fc), chunkSize);
HeapWord* const fc_addr = (HeapWord*) fc;
bool coalesce = false;
const size_t left = pointer_delta(fc_addr, freeFinger());
@@ -7725,20 +7430,16 @@
" out of bounds wrt _sp = [" PTR_FORMAT "," PTR_FORMAT ")"
" when examining fc = " PTR_FORMAT "(" SIZE_FORMAT ")",
p2i(eob), p2i(eob-1), p2i(_limit), p2i(_sp->bottom()), p2i(_sp->end()), p2i(fc), chunk_size);
if (eob >= _limit) {
assert(eob == _limit || fc->is_free(), "Only a free chunk should allow us to cross over the limit");
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr("_limit " PTR_FORMAT " reached or crossed by block "
+ log_develop(gc, sweep)("_limit " PTR_FORMAT " reached or crossed by block "
"[" PTR_FORMAT "," PTR_FORMAT ") in space "
"[" PTR_FORMAT "," PTR_FORMAT ")",
p2i(_limit), p2i(fc), p2i(eob), p2i(_sp->bottom()), p2i(_sp->end()));
- }
// Return the storage we are tracking back into the free lists.
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr("Flushing ... ");
- }
+ log_develop(gc, sweep)("Flushing ... ");
assert(freeFinger() < eob, "Error");
flush_cur_free_chunk( freeFinger(), pointer_delta(eob, freeFinger()));
}
}
@@ -7751,26 +7452,23 @@
FreeChunk* fc = (FreeChunk*) chunk;
fc->set_size(size);
assert(!_sp->verify_chunk_in_free_list(fc),
"chunk should not be in free lists yet");
}
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr(" -- add free block " PTR_FORMAT " (" SIZE_FORMAT ") to free lists",
- p2i(chunk), size);
- }
+ log_develop(gc, sweep)(" -- add free block " PTR_FORMAT " (" SIZE_FORMAT ") to free lists", p2i(chunk), size);
// A new free range is going to be starting. The current
// free range has not been added to the free lists yet or
// was removed so add it back.
// If the current free range was coalesced, then the death
// of the free range was recorded. Record a birth now.
if (lastFreeRangeCoalesced()) {
_sp->coalBirth(size);
}
_sp->addChunkAndRepairOffsetTable(chunk, size,
lastFreeRangeCoalesced());
- } else if (CMSTraceSweeper) {
- gclog_or_tty->print_cr("Already in free list: nothing to flush");
+ } else {
+ log_develop(gc, sweep)("Already in free list: nothing to flush");
}
set_inFreeRange(false);
set_freeRangeInFreeLists(false);
}
@@ -7797,13 +7495,11 @@
"CMS thread should hold CMS token");
_bitMap->lock()->unlock();
_freelistLock->unlock();
ConcurrentMarkSweepThread::desynchronize(true);
_collector->stopTimer();
- if (PrintCMSStatistics != 0) {
_collector->incrementYields();
- }
// See the comment in coordinator_yield()
for (unsigned i = 0; i < CMSYieldSleepCount &&
ConcurrentMarkSweepThread::should_yield() &&
!CMSCollector::foregroundGCIsActive(); ++i) {
@@ -7824,14 +7520,12 @@
return debug_cms_space->verify_chunk_in_free_list(fc);
}
#endif
void SweepClosure::print_free_block_coalesced(FreeChunk* fc) const {
- if (CMSTraceSweeper) {
- gclog_or_tty->print_cr("Sweep:coal_free_blk " PTR_FORMAT " (" SIZE_FORMAT ")",
+ log_develop(gc, sweep)("Sweep:coal_free_blk " PTR_FORMAT " (" SIZE_FORMAT ")",
p2i(fc), fc->size());
- }
}
// CMSIsAliveClosure
bool CMSIsAliveClosure::do_object_b(oop obj) {
HeapWord* addr = (HeapWord*)obj;
< prev index next >