< prev index next >

src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp

Print this page

        

*** 51,60 **** --- 51,61 ---- #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"
*** 1578,1588 **** 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); // 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); --- 1579,1589 ---- gc_timer->register_gc_start(); SerialOldTracer* gc_tracer = GenMarkSweep::gc_tracer(); gc_tracer->report_gc_start(gch->gc_cause(), gc_timer->gc_start()); ! 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);
*** 1961,1973 **** 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); ! } } void CMSCollector::register_gc_start(GCCause::Cause cause) { _cms_start_registered = true; _gc_timer_cm->register_gc_start(); --- 1962,1973 ---- if (TraceCMSState) { gclog_or_tty->print_cr("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) { _cms_start_registered = true; _gc_timer_cm->register_gc_start();
*** 2317,2328 **** } bool failed() { return _failed; } }; ! bool CMSCollector::verify_after_remark(bool silent) { ! if (!silent) gclog_or_tty->print(" [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"); --- 2317,2328 ---- } bool failed() { return _failed; } }; ! 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,2391 **** 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; --- 2381,2390 ----
*** 2840,2876 **** _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); ! } _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()); } - } } // CMS work // The common parts of CMSParInitialMarkTask and CMSParRemarkTask. --- 2839,2865 ---- _collector(collector), _phase(phase), _print_cr(print_cr) { if (PrintCMSStatistics != 0) { _collector->resetYields(); } ! log_info(gc)("%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(); ! log_info(gc)("%s-concurrent-%s: %3.3f/%3.3f secs", _collector->cmsGen()->short_name(), _phase, _collector->timerValue(), _wallclock.seconds()); if (PrintCMSStatistics != 0) { gclog_or_tty->print_cr(" (CMS-concurrent-%s yielded %d times)", _phase, _collector->yields()); } } // CMS work // The common parts of CMSParInitialMarkTask and CMSParRemarkTask.
*** 2933,2944 **** // 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);) // Reset all the PLAB chunk arrays if necessary. if (_survivor_plab_array != NULL && !CMSPLABRecordAlways) { reset_survivor_plab_arrays(); } --- 2922,2932 ---- // Setup the verification and class unloading state for this // CMS collection cycle. setup_cms_unloading_and_verification_state(); ! 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(); }
*** 3038,3048 **** // 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); bool res = markFromRootsWork(); if (res) { _collectorState = Precleaning; } else { // We failed and a foreground collection wants to take over --- 3026,3036 ---- // 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()); ! GCTraceCPUTime tcpu; CMSPhaseAccounting pa(this, "mark", !PrintGCDetails); bool res = markFromRootsWork(); if (res) { _collectorState = Precleaning; } else { // We failed and a foreground collection wants to take over
*** 3735,3745 **** * CMSScheduleRemarkEdenPenetration)) { _start_sampling = true; } else { _start_sampling = false; } ! TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); CMSPhaseAccounting pa(this, "preclean", !PrintGCDetails); preclean_work(CMSPrecleanRefLists1, CMSPrecleanSurvivors1); } CMSTokenSync x(true); // is cms thread if (CMSPrecleaningEnabled) { --- 3723,3733 ---- * CMSScheduleRemarkEdenPenetration)) { _start_sampling = true; } else { _start_sampling = false; } ! GCTraceCPUTime tcpu; CMSPhaseAccounting pa(this, "preclean", !PrintGCDetails); preclean_work(CMSPrecleanRefLists1, CMSPrecleanSurvivors1); } CMSTokenSync x(true); // is cms thread if (CMSPrecleaningEnabled) {
*** 3764,3774 **** // 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); // 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 --- 3752,3762 ---- // 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) { ! GCTraceCPUTime tcpu; CMSPhaseAccounting pa(this, "abortable-preclean", !PrintGCDetails); // 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
*** 4245,4256 **** 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);) gch->do_collection(true, // full (i.e. force, see below) false, // !clear_all_soft_refs 0, // size false, // is_tlab GenCollectedHeap::YoungGen // type --- 4233,4245 ---- 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); ! ! 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,4274 **** verify_work_stacks_empty(); verify_overflow_empty(); } void CMSCollector::checkpointRootsFinalWork() { ! NOT_PRODUCT(GCTraceTime tr("checkpointRootsFinalWork", PrintGCDetails, false, _gc_timer_cm);) assert(haveFreelistLocks(), "must have free list locks"); assert_lock_strong(bitMapLock()); ResourceMark rm; --- 4253,4263 ---- verify_work_stacks_empty(); verify_overflow_empty(); } void CMSCollector::checkpointRootsFinalWork() { ! GCTraceTime(Trace, gc) tm("checkpointRootsFinalWork", _gc_timer_cm); assert(haveFreelistLocks(), "must have free list locks"); assert_lock_strong(bitMapLock()); ResourceMark rm;
*** 4316,4337 **** // 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); do_remark_parallel(); } else { ! GCTraceTime t("Rescan (non-parallel) ", PrintGCDetails, false, _gc_timer_cm); do_remark_non_parallel(); } } verify_work_stacks_empty(); verify_overflow_empty(); { ! NOT_PRODUCT(GCTraceTime ts("refProcessingWork", PrintGCDetails, false, _gc_timer_cm);) refProcessingWork(); } verify_work_stacks_empty(); verify_overflow_empty(); --- 4305,4326 ---- // 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(Debug, gc) t("Rescan (parallel)", _gc_timer_cm); do_remark_parallel(); } else { ! GCTraceTime(Debug, gc) t("Rescan (non-parallel)", _gc_timer_cm); do_remark_non_parallel(); } } verify_work_stacks_empty(); verify_overflow_empty(); { ! GCTraceTime(Trace, gc) ts("refProcessingWork", _gc_timer_cm); refProcessingWork(); } verify_work_stacks_empty(); verify_overflow_empty();
*** 5102,5112 **** MarkFromDirtyCardsClosure markFromDirtyCardsClosure(this, _span, NULL, // space is set further below &_markBitMap, &_markStack, &mrias_cl); { ! GCTraceTime t("grey object rescan", PrintGCDetails, false, _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( --- 5091,5101 ---- MarkFromDirtyCardsClosure markFromDirtyCardsClosure(this, _span, NULL, // space is set further below &_markBitMap, &_markStack, &mrias_cl); { ! 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(
*** 5139,5149 **** GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) { HandleMark hm; // Discard invalid handles created during verification Universe::verify(); } { ! GCTraceTime t("root rescan", PrintGCDetails, false, _gc_timer_cm); verify_work_stacks_empty(); gch->rem_set()->prepare_for_younger_refs_iterate(false); // Not parallel. StrongRootsScope srs(1); --- 5128,5138 ---- GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) { HandleMark hm; // Discard invalid handles created during verification Universe::verify(); } { ! 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,5171 **** || (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); verify_work_stacks_empty(); // Scan all class loader data objects that might have been introduced // during concurrent marking. --- 5150,5160 ---- || (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(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,5190 **** verify_work_stacks_empty(); } { ! GCTraceTime t("dirty klass scan", PrintGCDetails, false, _gc_timer_cm); verify_work_stacks_empty(); RemarkKlassClosure remark_klass_closure(&mrias_cl); ClassLoaderDataGraph::classes_do(&remark_klass_closure); --- 5169,5179 ---- verify_work_stacks_empty(); } { ! 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);
*** 5388,5398 **** &_markStack, false /* !preclean */); CMSDrainMarkingStackClosure cmsDrainMarkingStackClosure(this, _span, &_markBitMap, &_markStack, &cmsKeepAliveClosure, false /* !preclean */); { ! GCTraceTime t("weak refs processing", PrintGCDetails, false, _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 --- 5377,5387 ---- &_markStack, false /* !preclean */); CMSDrainMarkingStackClosure cmsDrainMarkingStackClosure(this, _span, &_markBitMap, &_markStack, &cmsKeepAliveClosure, false /* !preclean */); { ! 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,5440 **** // 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); // Unload classes and purge the SystemDictionary. bool purged_class = SystemDictionary::do_unloading(&_is_alive_closure); // Unload nmethods. --- 5419,5429 ---- // This is the point where the entire marking should have completed. verify_work_stacks_empty(); if (should_unload_classes()) { { ! 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,5459 **** // 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); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } { ! GCTraceTime t("scrub string table", PrintGCDetails, false, _gc_timer_cm); // Delete entries for dead interned strings. StringTable::unlink(&_is_alive_closure); } } --- 5432,5448 ---- // Prune dead klasses from subklass/sibling/implementor lists. Klass::clean_weak_klass_links(&_is_alive_closure); } { ! GCTraceTime(Debug, gc) t("scrub symbol table", _gc_timer_cm); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } { ! GCTraceTime(Debug, gc) t("scrub string table", _gc_timer_cm); // Delete entries for dead interned strings. StringTable::unlink(&_is_alive_closure); } }
*** 5516,5526 **** 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); // First sweep the old gen { CMSTokenSyncWithLocks ts(true, _cmsGen->freelistLock(), bitMapLock()); --- 5505,5515 ---- assert(!_intra_sweep_timer.is_active(), "Should not be active"); _intra_sweep_timer.reset(); _intra_sweep_timer.start(); { ! GCTraceCPUTime tcpu; CMSPhaseAccounting pa(this, "sweep", !PrintGCDetails); // First sweep the old gen { CMSTokenSyncWithLocks ts(true, _cmsGen->freelistLock(), bitMapLock());
*** 5700,5710 **** 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); HeapWord* curAddr = _markBitMap.startWord(); while (curAddr < _markBitMap.endWord()) { size_t remaining = pointer_delta(_markBitMap.endWord(), curAddr); --- 5689,5699 ---- return; } // Clear the mark bitmap (no grey objects to start with) // for the next cycle. ! GCTraceCPUTime tcpu; CMSPhaseAccounting cmspa(this, "reset", !PrintGCDetails); HeapWord* curAddr = _markBitMap.startWord(); while (curAddr < _markBitMap.endWord()) { size_t remaining = pointer_delta(_markBitMap.endWord(), curAddr);
*** 5756,5779 **** _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); TraceCollectorStats tcs(counters()); switch (op) { case CMS_op_checkpointRootsInitial: { SvcGCMarker sgcm(SvcGCMarker::OTHER); checkpointRootsInitial(); if (PrintGC) { _cmsGen->printOccupancy("initial-mark"); } break; } case CMS_op_checkpointRootsFinal: { SvcGCMarker sgcm(SvcGCMarker::OTHER); checkpointRootsFinal(); if (PrintGC) { _cmsGen->printOccupancy("remark"); } --- 5745,5769 ---- _collectorState = Idling; register_gc_end(); } void CMSCollector::do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause) { ! GCTraceCPUTime tcpu; TraceCollectorStats tcs(counters()); switch (op) { case CMS_op_checkpointRootsInitial: { + GCTraceTime(Info, gc) t("GC pause, initial mark"); SvcGCMarker sgcm(SvcGCMarker::OTHER); checkpointRootsInitial(); if (PrintGC) { _cmsGen->printOccupancy("initial-mark"); } break; } case CMS_op_checkpointRootsFinal: { + GCTraceTime(Info, gc) t("GC pause, remark"); SvcGCMarker sgcm(SvcGCMarker::OTHER); checkpointRootsFinal(); if (PrintGC) { _cmsGen->printOccupancy("remark"); }
< prev index next >