--- old/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp 2015-11-19 15:35:01.642129458 +0100 +++ new/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp 2015-11-19 15:35:01.522129462 +0100 @@ -53,6 +53,7 @@ #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" @@ -366,13 +367,10 @@ 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, - cms_free, expected_promotion); - gclog_or_tty->print_cr(" cms_free_dbl %f cms_consumption_rate %f", - cms_free_dbl, cms_consumption_rate() + 1.0); - } + log_trace(gc, stats)("CMSStats::time_until_cms_gen_full: cms_free " SIZE_FORMAT " expected_promotion " SIZE_FORMAT, + cms_free, expected_promotion); + 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); } @@ -401,12 +399,8 @@ // 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; @@ -668,31 +662,6 @@ } #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 @@ -716,21 +685,18 @@ 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()); } } @@ -786,27 +752,26 @@ 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"); @@ -1144,10 +1109,7 @@ 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; } @@ -1155,24 +1117,21 @@ // ------------------------------------------------------------------ // 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()); } // ------------------------------------------------------------------ @@ -1190,12 +1149,8 @@ // 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; } } @@ -1207,9 +1162,7 @@ // 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; } @@ -1220,16 +1173,12 @@ 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; } @@ -1243,13 +1192,11 @@ // 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)", - stats().cms_time_since_begin()); - } else { - gclog_or_tty->print_cr("CMSCollector: collect because of trigger interval (first collection)"); - } + if (stats().valid()) { + log_trace(gc)("CMSCollector: collect because of trigger interval (time since last begin %3.7f secs)", + stats().cms_time_since_begin()); + } else { + log_trace(gc)("CMSCollector: collect because of trigger interval (first collection)"); } return true; } @@ -1292,20 +1239,15 @@ assert_lock_strong(freelistLock()); if (occupancy() > initiating_occupancy()) { - if (PrintGCDetails && Verbose) { - gclog_or_tty->print(" %s: collect because of occupancy %f / %f ", - short_name(), occupancy(), initiating_occupancy()); - } + 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; @@ -1362,13 +1304,9 @@ 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(); } } @@ -1502,11 +1440,9 @@ "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. @@ -1580,7 +1516,7 @@ 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. @@ -1665,33 +1601,34 @@ } 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 ")", - 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, - _eden_chunk_index, _eden_chunk_capacity); + 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()); + 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 ")", - 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, - _survivor_chunk_index, _survivor_chunk_capacity); + 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()); + 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])); } } } @@ -1780,11 +1717,7 @@ _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 @@ -1795,10 +1728,8 @@ // 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", - p2i(Thread::current()), _collectorState); - } + 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) @@ -1828,11 +1759,8 @@ // 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", - p2i(Thread::current()), _collectorState); - } + 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 @@ -1936,10 +1864,8 @@ ShouldNotReachHere(); break; } - if (TraceCMSState) { - gclog_or_tty->print_cr(" Thread " INTPTR_FORMAT " done - next CMS state %d", - p2i(Thread::current()), _collectorState); - } + log_debug(gc, state)(" Thread " INTPTR_FORMAT " done - next CMS state %d", + p2i(Thread::current()), _collectorState); assert(_foregroundGCShouldWait, "block post-condition"); } @@ -1958,14 +1884,10 @@ 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", - p2i(Thread::current()), _collectorState); - } - if (PrintGC && Verbose) { - _cmsGen->print_heap_change(prev_used); - } + log_debug(gc, state)("CMS Thread " INTPTR_FORMAT " exiting collection CMS state %d", + p2i(Thread::current()), _collectorState); + 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) { @@ -2017,10 +1939,8 @@ 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", - p2i(Thread::current()), _collectorState); - } + 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); } @@ -2029,10 +1949,8 @@ 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", - p2i(Thread::current()), _collectorState); - } + log_debug(gc, state)("CMS Thread " INTPTR_FORMAT " continuing at CMS state %d", + p2i(Thread::current()), _collectorState); return res; } @@ -2129,11 +2047,8 @@ 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", - _numObjectsAllocated, _numWordsAllocated*sizeof(HeapWord)); - } + log_develop(gc, alloc)("Allocated " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes concurrently", + _numObjectsAllocated, _numWordsAllocated*sizeof(HeapWord)); _numObjectsAllocated = 0; _numWordsAllocated = 0; ) @@ -2210,21 +2125,15 @@ NOT_PRODUCT( assert(_numObjectsAllocated == 0, "check"); assert(_numWordsAllocated == 0, "check"); - if (Verbose && PrintGC) { - gclog_or_tty->print("Promoted " SIZE_FORMAT " objects, " - SIZE_FORMAT " bytes", - _numObjectsPromoted, _numWordsPromoted*sizeof(HeapWord)); - } + 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()); - } + // Call down the chain in contiguous_available needs the freelistLock + // so print this out before releasing the freeListLock. + log_develop(gc)(" Contiguous available " SIZE_FORMAT " bytes ", contiguous_available()); } #ifndef PRODUCT @@ -2242,40 +2151,6 @@ } #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; @@ -2309,8 +2184,10 @@ 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; @@ -2319,8 +2196,8 @@ 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; @@ -2383,7 +2260,6 @@ warning("Unrecognized value " UINTX_FORMAT " for CMSRemarkVerifyVariant", CMSRemarkVerifyVariant); } - if (!silent) gclog_or_tty->print(" done] "); return true; } @@ -2435,8 +2311,10 @@ 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"); } } @@ -2729,10 +2607,7 @@ // 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)); } } @@ -2800,9 +2675,7 @@ 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; } @@ -2812,63 +2685,36 @@ 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) { - - 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); - } + const char *title) : + _collector(collector), _title(title), _trace_time(title) { + + _collector->resetYields(); _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 @@ -2935,8 +2781,7 @@ // 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) { @@ -2967,9 +2812,7 @@ // the klasses. The claimed marks need to be cleared before marking starts. ClassLoaderDataGraph::clear_claimed_marks(); - if (CMSPrintEdenSurvivorChunks) { - print_eden_and_survivor_chunk_arrays(); - } + print_eden_and_survivor_chunk_arrays(); { #if defined(COMPILER2) || INCLUDE_JVMCI @@ -3040,17 +2883,15 @@ // 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; @@ -3255,22 +3096,14 @@ _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 @@ -3485,10 +3318,7 @@ 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 || @@ -3573,9 +3403,7 @@ _bit_map_lock->unlock(); ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _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 @@ -3737,8 +3565,8 @@ } 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 @@ -3766,8 +3594,8 @@ // 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 @@ -3789,15 +3617,11 @@ // 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 @@ -3810,10 +3634,8 @@ waited++; } } - if (PrintCMSStatistics > 0) { - gclog_or_tty->print(" [" SIZE_FORMAT " iterations, " SIZE_FORMAT " waits, " SIZE_FORMAT " cards)] ", - loops, waited, cumworkdone); - } + 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) { @@ -3957,9 +3779,7 @@ 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 @@ -3979,10 +3799,8 @@ 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)", - curNumCards, cumNumCards, numIter); - } + 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 } @@ -4236,19 +4054,17 @@ 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 @@ -4266,7 +4082,7 @@ } 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()); @@ -4298,9 +4114,7 @@ // Update the saved marks which may affect the root scans. gch->save_marks(); - if (CMSPrintEdenSurvivorChunks) { - print_eden_and_survivor_chunk_arrays(); - } + print_eden_and_survivor_chunk_arrays(); { #if defined(COMPILER2) || INCLUDE_JVMCI @@ -4318,10 +4132,10 @@ // 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(); } } @@ -4329,7 +4143,7 @@ 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(); @@ -4348,13 +4162,8 @@ 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; @@ -4362,26 +4171,19 @@ _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 ")", - _par_pmc_remark_ovflw, _par_kac_ovflw); - } - _par_pmc_remark_ovflw = 0; + 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 ")", - _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()); - } - } + if (_markStack._hit_limit > 0) { + log_debug(gc, stats)(" (benign) Hit max stack size limit (" SIZE_FORMAT ")", + _markStack._hit_limit); + } + if (_markStack._failed_double > 0) { + 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; @@ -4415,11 +4217,7 @@ { 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 -------------- @@ -4440,11 +4238,7 @@ || (_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 @@ -4557,11 +4351,7 @@ { 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 -------------- @@ -4580,11 +4370,7 @@ || (_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. @@ -4603,11 +4389,7 @@ 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 ---------- @@ -4620,11 +4402,7 @@ 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 @@ -4642,11 +4420,7 @@ // "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. @@ -4654,11 +4428,7 @@ _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. @@ -4852,11 +4622,7 @@ 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"); } @@ -4953,9 +4719,7 @@ } // 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; @@ -4967,10 +4731,8 @@ // 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 ") ", - i, p2i(_survivor_chunk_array[i])); - } + 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"); } @@ -5104,7 +4866,7 @@ 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. { @@ -5129,10 +4891,7 @@ _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 && @@ -5141,7 +4900,7 @@ Universe::verify(); } { - GCTraceTime t("root rescan", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime(Trace, gc) t("Root Rescan", _gc_timer_cm); verify_work_stacks_empty(); @@ -5163,7 +4922,7 @@ } { - GCTraceTime t("visit unhandled CLDs", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime(Trace, gc) t("Visit Unhandled CLDs", _gc_timer_cm); verify_work_stacks_empty(); @@ -5182,7 +4941,7 @@ } { - GCTraceTime t("dirty klass scan", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime(Trace, gc) t("Dirty Klass Scan", _gc_timer_cm); verify_work_stacks_empty(); @@ -5344,11 +5103,7 @@ 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) @@ -5390,7 +5145,7 @@ _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()) { @@ -5432,7 +5187,7 @@ 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); @@ -5445,13 +5200,13 @@ } { - 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); } @@ -5518,8 +5273,8 @@ _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(), @@ -5602,13 +5357,8 @@ 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); } @@ -5702,8 +5452,8 @@ // 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()) { @@ -5719,9 +5469,7 @@ bitMapLock()->unlock(); ConcurrentMarkSweepThread::desynchronize(true); stopTimer(); - if (PrintCMSStatistics != 0) { - incrementYields(); - } + incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; i < CMSYieldSleepCount && @@ -5758,25 +5506,20 @@ } 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: @@ -5989,9 +5732,9 @@ 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; } @@ -6011,12 +5754,11 @@ _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", - _capacity / K, new_capacity / K); + log_debug(gc)(" (benign) Failed to expand marking stack from " SIZE_FORMAT "K to " SIZE_FORMAT "K", + _capacity / K, new_capacity / K); } } @@ -6093,8 +5835,10 @@ 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"); } } @@ -6190,9 +5934,7 @@ _freelistLock->unlock(); ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _collector->incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; @@ -6348,9 +6090,7 @@ _freelistLock->unlock(); ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _collector->incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; i < CMSYieldSleepCount && @@ -6417,9 +6157,7 @@ _bit_map->lock()->unlock(); ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _collector->incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; i < CMSYieldSleepCount && @@ -6572,9 +6310,7 @@ _bitMap->lock()->unlock(); ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _collector->incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; i < CMSYieldSleepCount && @@ -6880,17 +6616,15 @@ // 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); } @@ -6990,10 +6724,7 @@ } ) 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); } @@ -7042,10 +6773,7 @@ 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 || @@ -7207,9 +6935,7 @@ ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _collector->incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; i < CMSYieldSleepCount && @@ -7240,10 +6966,7 @@ // 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); } @@ -7276,10 +6999,8 @@ ) 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 { @@ -7306,42 +7027,32 @@ print(); ShouldNotReachHere(); } - if (Verbose && PrintGC) { - gclog_or_tty->print("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); - - if (PrintCMSStatistics && 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)); + + if (log_is_enabled(Debug, gc, sweep)) { + log_debug(gc, sweep)("Collected " SIZE_FORMAT " objects, " SIZE_FORMAT " bytes", + _numObjectsFreed, _numWordsFreed*sizeof(HeapWord)); + 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 (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; + 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", - p2i(freeFinger), freeRangeInFreeLists); - } + 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); @@ -7407,13 +7118,9 @@ "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", - p2i(freeFinger()), pointer_delta(addr, freeFinger()), - lastFreeRangeCoalesced() ? 1 : 0); - } + 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 @@ -7624,9 +7331,7 @@ 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; @@ -7727,16 +7432,12 @@ 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 " - "[" PTR_FORMAT "," PTR_FORMAT ") in space " - "[" PTR_FORMAT "," PTR_FORMAT ")", - p2i(_limit), p2i(fc), p2i(eob), p2i(_sp->bottom()), p2i(_sp->end())); - } + 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())); } @@ -7753,10 +7454,7 @@ 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. @@ -7767,8 +7465,8 @@ } _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); @@ -7799,9 +7497,7 @@ _freelistLock->unlock(); ConcurrentMarkSweepThread::desynchronize(true); _collector->stopTimer(); - if (PrintCMSStatistics != 0) { - _collector->incrementYields(); - } + _collector->incrementYields(); // See the comment in coordinator_yield() for (unsigned i = 0; i < CMSYieldSleepCount && @@ -7826,10 +7522,8 @@ #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 ")", - p2i(fc), fc->size()); - } + log_develop(gc, sweep)("Sweep:coal_free_blk " PTR_FORMAT " (" SIZE_FORMAT ")", + p2i(fc), fc->size()); } // CMSIsAliveClosure