diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -1999,7 +1999,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 t("CMS:MSC ", PrintGCDetails && Verbose, true, NULL, gc_tracer->gc_id()); if (PrintGC && Verbose && !(GCCause::is_user_requested_gc(gch->gc_cause()))) { gclog_or_tty->print_cr("Compact ConcurrentMarkSweepGeneration after %d " "collections passed to foreground collector", _full_gcs_since_conc_gc); @@ -2509,8 +2509,10 @@ assert(ConcurrentMarkSweepThread::vm_thread_has_cms_token(), "VM thread should have CMS token"); + // The gc id is created in register_foreground_gc_start if this collection is synchronous + const GCId gc_id = _collectorState == InitialMarking ? GCId::peek() : _gc_tracer_cm->gc_id(); NOT_PRODUCT(GCTraceTime t("CMS:MS (foreground) ", PrintGCDetails && Verbose, - true, NULL);) + true, NULL, gc_id);) if (UseAdaptiveSizePolicy) { size_policy()->ms_collection_begin(); } @@ -3527,6 +3529,7 @@ public: CMSPhaseAccounting(CMSCollector *collector, const char *phase, + const GCId gc_id, bool print_cr = true); ~CMSPhaseAccounting(); @@ -3535,6 +3538,7 @@ const char *_phase; elapsedTimer _wallclock; bool _print_cr; + const GCId _gc_id; public: // Not MT-safe; so do not pass around these StackObj's @@ -3550,15 +3554,15 @@ CMSPhaseAccounting::CMSPhaseAccounting(CMSCollector *collector, const char *phase, + const GCId gc_id, bool print_cr) : - _collector(collector), _phase(phase), _print_cr(print_cr) { + _collector(collector), _phase(phase), _print_cr(print_cr), _gc_id(gc_id) { if (PrintCMSStatistics != 0) { _collector->resetYields(); } if (PrintGCDetails) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(_gc_id); gclog_or_tty->print_cr("[%s-concurrent-%s-start]", _collector->cmsGen()->short_name(), _phase); } @@ -3572,8 +3576,7 @@ _collector->stopTimer(); _wallclock.stop(); if (PrintGCDetails) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(_gc_id); gclog_or_tty->print("[%s-concurrent-%s: %3.3f/%3.3f secs]", _collector->cmsGen()->short_name(), _phase, _collector->timerValue(), _wallclock.seconds()); @@ -3671,7 +3674,7 @@ setup_cms_unloading_and_verification_state(); NOT_PRODUCT(GCTraceTime t("\ncheckpointRootsInitialWork", - PrintGCDetails && Verbose, true, _gc_timer_cm);) + PrintGCDetails && Verbose, true, _gc_timer_cm, _gc_tracer_cm->gc_id());) if (UseAdaptiveSizePolicy) { size_policy()->checkpoint_roots_initial_begin(); } @@ -3796,7 +3799,7 @@ CMSTokenSyncWithLocks ts(true, bitMapLock()); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - CMSPhaseAccounting pa(this, "mark", !PrintGCDetails); + CMSPhaseAccounting pa(this, "mark", _gc_tracer_cm->gc_id(), !PrintGCDetails); res = markFromRootsWork(asynch); if (res) { _collectorState = Precleaning; @@ -4519,7 +4522,7 @@ _start_sampling = false; } TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - CMSPhaseAccounting pa(this, "preclean", !PrintGCDetails); + CMSPhaseAccounting pa(this, "preclean", _gc_tracer_cm->gc_id(), !PrintGCDetails); preclean_work(CMSPrecleanRefLists1, CMSPrecleanSurvivors1); } CMSTokenSync x(true); // is cms thread @@ -4548,7 +4551,7 @@ // 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); + CMSPhaseAccounting pa(this, "abortable-preclean", _gc_tracer_cm->gc_id(), !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 @@ -4693,7 +4696,7 @@ GCTimer *gc_timer = NULL; // Currently not tracing concurrent phases rp->preclean_discovered_references( rp->is_alive_non_header(), &keep_alive, &complete_trace, &yield_cl, - gc_timer); + gc_timer, _gc_tracer_cm->gc_id()); } if (clean_survivor) { // preclean the active survivor space(s) @@ -5036,7 +5039,7 @@ // 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);) + PrintGCDetails && Verbose, true, _gc_timer_cm, _gc_tracer_cm->gc_id());) int level = _cmsGen->level() - 1; if (level >= 0) { gch->do_collection(true, // full (i.e. force, see below) @@ -5065,7 +5068,7 @@ void CMSCollector::checkpointRootsFinalWork(bool asynch, bool clear_all_soft_refs, bool init_mark_was_synchronous) { - NOT_PRODUCT(GCTraceTime tr("checkpointRootsFinalWork", PrintGCDetails, false, _gc_timer_cm);) + NOT_PRODUCT(GCTraceTime tr("checkpointRootsFinalWork", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id());) assert(haveFreelistLocks(), "must have free list locks"); assert_lock_strong(bitMapLock()); @@ -5120,11 +5123,11 @@ // the most recent young generation GC, minus those cleaned up by the // concurrent precleaning. if (CMSParallelRemarkEnabled && CollectedHeap::use_parallel_gc_threads()) { - GCTraceTime t("Rescan (parallel) ", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("Rescan (parallel) ", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); do_remark_parallel(); } else { GCTraceTime t("Rescan (non-parallel) ", PrintGCDetails, false, - _gc_timer_cm); + _gc_timer_cm, _gc_tracer_cm->gc_id()); do_remark_non_parallel(); } } @@ -5137,7 +5140,7 @@ verify_overflow_empty(); { - NOT_PRODUCT(GCTraceTime ts("refProcessingWork", PrintGCDetails, false, _gc_timer_cm);) + NOT_PRODUCT(GCTraceTime ts("refProcessingWork", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id());) refProcessingWork(asynch, clear_all_soft_refs); } verify_work_stacks_empty(); @@ -5922,7 +5925,7 @@ NULL, // space is set further below &_markBitMap, &_markStack, &mrias_cl); { - GCTraceTime t("grey object rescan", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("grey object rescan", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); // Iterate over the dirty cards, setting the corresponding bits in the // mod union table. { @@ -5959,7 +5962,7 @@ Universe::verify(); } { - GCTraceTime t("root rescan", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("root rescan", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); verify_work_stacks_empty(); @@ -5981,7 +5984,7 @@ } { - GCTraceTime t("visit unhandled CLDs", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("visit unhandled CLDs", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); verify_work_stacks_empty(); @@ -6000,7 +6003,7 @@ } { - GCTraceTime t("dirty klass scan", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("dirty klass scan", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); verify_work_stacks_empty(); @@ -6202,7 +6205,7 @@ _span, &_markBitMap, &_markStack, &cmsKeepAliveClosure, false /* !preclean */); { - GCTraceTime t("weak refs processing", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("weak refs processing", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); ReferenceProcessorStats stats; if (rp->processing_is_mt()) { @@ -6227,13 +6230,15 @@ &cmsKeepAliveClosure, &cmsDrainMarkingStackClosure, &task_executor, - _gc_timer_cm); + _gc_timer_cm, + _gc_tracer_cm->gc_id()); } else { stats = rp->process_discovered_references(&_is_alive_closure, &cmsKeepAliveClosure, &cmsDrainMarkingStackClosure, NULL, - _gc_timer_cm); + _gc_timer_cm, + _gc_tracer_cm->gc_id()); } _gc_tracer_cm->report_gc_reference_stats(stats); @@ -6244,7 +6249,7 @@ if (should_unload_classes()) { { - GCTraceTime t("class unloading", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("class unloading", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); // Unload classes and purge the SystemDictionary. bool purged_class = SystemDictionary::do_unloading(&_is_alive_closure); @@ -6257,7 +6262,7 @@ } { - GCTraceTime t("scrub symbol table", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("scrub symbol table", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } @@ -6266,7 +6271,7 @@ // CMS doesn't use the StringTable as hard roots when class unloading is turned off. // Need to check if we really scanned the StringTable. if ((roots_scanning_options() & SharedHeap::SO_Strings) == 0) { - GCTraceTime t("scrub string table", PrintGCDetails, false, _gc_timer_cm); + GCTraceTime t("scrub string table", PrintGCDetails, false, _gc_timer_cm, _gc_tracer_cm->gc_id()); // Delete entries for dead interned strings. StringTable::unlink(&_is_alive_closure); } @@ -6333,7 +6338,7 @@ _intra_sweep_timer.start(); if (asynch) { TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - CMSPhaseAccounting pa(this, "sweep", !PrintGCDetails); + CMSPhaseAccounting pa(this, "sweep", _gc_tracer_cm->gc_id(), !PrintGCDetails); // First sweep the old gen { CMSTokenSyncWithLocks ts(true, _cmsGen->freelistLock(), @@ -6554,7 +6559,7 @@ // 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); + CMSPhaseAccounting cmspa(this, "reset", _gc_tracer_cm->gc_id(), !PrintGCDetails); HeapWord* curAddr = _markBitMap.startWord(); while (curAddr < _markBitMap.endWord()) { @@ -6620,7 +6625,7 @@ void CMSCollector::do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause) { gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - GCTraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, NULL); + GCTraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, NULL, _gc_tracer_cm->gc_id()); TraceCollectorStats tcs(counters()); switch (op) {