< 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"
@@ -1578,11 +1579,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);
@@ -1961,13 +1962,12 @@
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_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,12 +2317,12 @@
}
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 +2381,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;
@@ -2840,37 +2839,27 @@
_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);
- }
+ 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();
- if (PrintGCDetails) {
- gclog_or_tty->gclog_stamp();
- gclog_or_tty->print("[%s-concurrent-%s: %3.3f/%3.3f secs]",
+ log_info(gc)("%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.
@@ -2933,12 +2922,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();
}
@@ -3038,11 +3026,11 @@
// 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);
+ 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,11 +3723,11 @@
* CMSScheduleRemarkEdenPenetration)) {
_start_sampling = true;
} else {
_start_sampling = false;
}
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
+ GCTraceCPUTime tcpu;
CMSPhaseAccounting pa(this, "preclean", !PrintGCDetails);
preclean_work(CMSPrecleanRefLists1, CMSPrecleanSurvivors1);
}
CMSTokenSync x(true); // is cms thread
if (CMSPrecleaningEnabled) {
@@ -3764,11 +3752,11 @@
// 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);
+ 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,12 +4233,13 @@
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 +4253,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;
@@ -4316,22 +4305,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();
@@ -5102,11 +5091,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(
@@ -5139,11 +5128,11 @@
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 +5150,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 +5169,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);
@@ -5388,11 +5377,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 +5419,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 +5432,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,11 +5505,11 @@
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);
+ GCTraceCPUTime tcpu;
CMSPhaseAccounting pa(this, "sweep", !PrintGCDetails);
// First sweep the old gen
{
CMSTokenSyncWithLocks ts(true, _cmsGen->freelistLock(),
bitMapLock());
@@ -5700,11 +5689,11 @@
return;
}
// Clear the mark bitmap (no grey objects to start with)
// for the next cycle.
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
+ GCTraceCPUTime tcpu;
CMSPhaseAccounting cmspa(this, "reset", !PrintGCDetails);
HeapWord* curAddr = _markBitMap.startWord();
while (curAddr < _markBitMap.endWord()) {
size_t remaining = pointer_delta(_markBitMap.endWord(), curAddr);
@@ -5756,24 +5745,25 @@
_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("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 >