# HG changeset patch # User brutisso # Date 1403177474 -7200 # Node ID 0982ec23da03d077f02dd8e9ff292e456101b8cb # Parent 5d855d021755ef19aed9c483df6c678199bbcd1d 8043607: Add a GC id as a log decoration similar to PrintGCTimeStamps Reviewed-by: jwilhelm, ehelin, tschatzl 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) { diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp --- a/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -64,7 +64,7 @@ void VM_CMS_Operation::verify_before_gc() { if (VerifyBeforeGC && GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) { - GCTraceTime tm("Verify Before", false, false, _collector->_gc_timer_cm); + GCTraceTime tm("Verify Before", false, false, _collector->_gc_timer_cm, _collector->_gc_tracer_cm->gc_id()); HandleMark hm; FreelistLocker x(_collector); MutexLockerEx y(_collector->bitMapLock(), Mutex::_no_safepoint_check_flag); @@ -76,7 +76,7 @@ void VM_CMS_Operation::verify_after_gc() { if (VerifyAfterGC && GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) { - GCTraceTime tm("Verify After", false, false, _collector->_gc_timer_cm); + GCTraceTime tm("Verify After", false, false, _collector->_gc_timer_cm, _collector->_gc_tracer_cm->gc_id()); HandleMark hm; FreelistLocker x(_collector); MutexLockerEx y(_collector->bitMapLock(), Mutex::_no_safepoint_check_flag); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/g1/concurrentMark.cpp --- a/src/share/vm/gc_implementation/g1/concurrentMark.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/g1/concurrentMark.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -510,6 +510,7 @@ _has_overflown(false), _concurrent(false), _has_aborted(false), + _aborted_gc_id(GCId::undefined()), _restart_for_overflow(false), _concurrent_marking_in_progress(false), @@ -1019,8 +1020,7 @@ force_overflow()->update(); if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-mark-reset-for-overflow]"); } } @@ -2464,7 +2464,7 @@ if (G1Log::finer()) { gclog_or_tty->put(' '); } - GCTraceTime t("GC ref-proc", G1Log::finer(), false, g1h->gc_timer_cm()); + GCTraceTime t("GC ref-proc", G1Log::finer(), false, g1h->gc_timer_cm(), concurrent_gc_id()); ReferenceProcessor* rp = g1h->ref_processor_cm(); @@ -2521,7 +2521,8 @@ &g1_keep_alive, &g1_drain_mark_stack, executor, - g1h->gc_timer_cm()); + g1h->gc_timer_cm(), + concurrent_gc_id()); g1h->gc_tracer_cm()->report_gc_reference_stats(stats); // The do_oop work routines of the keep_alive and drain_marking_stack @@ -3252,6 +3253,12 @@ } _first_overflow_barrier_sync.abort(); _second_overflow_barrier_sync.abort(); + const GCId& gc_id = _g1h->gc_tracer_cm()->gc_id(); + if (!gc_id.is_undefined()) { + // We can do multiple full GCs before ConcurrentMarkThread::run() gets a chance + // to detect that it was aborted. Only keep track of the first GC id that we aborted. + _aborted_gc_id = gc_id; + } _has_aborted = true; SATBMarkQueueSet& satb_mq_set = JavaThread::satb_mark_queue_set(); @@ -3266,6 +3273,13 @@ _g1h->register_concurrent_cycle_end(); } +const GCId& ConcurrentMark::concurrent_gc_id() { + if (has_aborted()) { + return _aborted_gc_id; + } + return _g1h->gc_tracer_cm()->gc_id(); +} + static void print_ms_time_info(const char* prefix, const char* name, NumberSeq& ns) { gclog_or_tty->print_cr("%s%5d %12s: total time = %8.2f s (avg = %8.2f ms).", diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/g1/concurrentMark.hpp --- a/src/share/vm/gc_implementation/g1/concurrentMark.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/g1/concurrentMark.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -26,6 +26,7 @@ #define SHARE_VM_GC_IMPLEMENTATION_G1_CONCURRENTMARK_HPP #include "gc_implementation/g1/heapRegionSet.hpp" +#include "gc_implementation/shared/gcId.hpp" #include "utilities/taskqueue.hpp" class G1CollectedHeap; @@ -444,6 +445,7 @@ volatile bool _concurrent; // set at the end of a Full GC so that marking aborts volatile bool _has_aborted; + GCId _aborted_gc_id; // used when remark aborts due to an overflow to indicate that // another concurrent marking phase should start @@ -825,6 +827,8 @@ bool has_aborted() { return _has_aborted; } + const GCId& concurrent_gc_id(); + // This prints the global/local fingers. It is used for debugging. NOT_PRODUCT(void print_finger();) diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/g1/concurrentMarkThread.cpp --- a/src/share/vm/gc_implementation/g1/concurrentMarkThread.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/g1/concurrentMarkThread.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -1,4 +1,4 @@ -/* + /* * Copyright (c) 2001, 2013, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * @@ -29,6 +29,7 @@ #include "gc_implementation/g1/g1Log.hpp" #include "gc_implementation/g1/g1MMUTracker.hpp" #include "gc_implementation/g1/vm_operations_g1.hpp" +#include "gc_implementation/shared/gcTrace.hpp" #include "memory/resourceArea.hpp" #include "runtime/vmThread.hpp" @@ -109,8 +110,7 @@ double scan_start = os::elapsedTime(); if (!cm()->has_aborted()) { if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]"); } @@ -118,8 +118,7 @@ double scan_end = os::elapsedTime(); if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf secs]", scan_end - scan_start); } @@ -127,8 +126,7 @@ double mark_start_sec = os::elapsedTime(); if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-mark-start]"); } @@ -151,8 +149,7 @@ } if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-mark-end, %1.7lf secs]", mark_end_sec - mark_start_sec); } @@ -167,8 +164,7 @@ "in remark (restart #%d).", iter); } if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-mark-restart-for-overflow]"); } } @@ -212,8 +208,7 @@ double cleanup_start_sec = os::elapsedTime(); if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-cleanup-start]"); } @@ -233,8 +228,7 @@ double cleanup_end_sec = os::elapsedTime(); if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-cleanup-end, %1.7lf secs]", cleanup_end_sec - cleanup_start_sec); } @@ -274,8 +268,7 @@ if (cm()->has_aborted()) { if (G1Log::fine()) { - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(cm()->concurrent_gc_id()); gclog_or_tty->print_cr("[GC concurrent-mark-abort]"); } } diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -1305,7 +1305,7 @@ TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); { - GCTraceTime t(GCCauseString("Full GC", gc_cause()), G1Log::fine(), true, NULL); + GCTraceTime t(GCCauseString("Full GC", gc_cause()), G1Log::fine(), true, NULL, gc_tracer->gc_id()); TraceCollectorStats tcs(g1mm()->full_collection_counters()); TraceMemoryManagerStats tms(true /* fullGC */, gc_cause()); @@ -3893,8 +3893,7 @@ return; } - gclog_or_tty->date_stamp(PrintGCDateStamps); - gclog_or_tty->stamp(PrintGCTimeStamps); + gclog_or_tty->gclog_stamp(_gc_tracer_stw->gc_id()); GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) .append(g1_policy()->gcs_are_young() ? "(young)" : "(mixed)") @@ -5781,7 +5780,8 @@ &keep_alive, &drain_queue, NULL, - _gc_timer_stw); + _gc_timer_stw, + _gc_tracer_stw->gc_id()); } else { // Parallel reference processing assert(rp->num_q() == no_of_gc_workers, "sanity"); @@ -5792,7 +5792,8 @@ &keep_alive, &drain_queue, &par_task_executor, - _gc_timer_stw); + _gc_timer_stw, + _gc_tracer_stw->gc_id()); } _gc_tracer_stw->report_gc_reference_stats(stats); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/g1/g1MarkSweep.cpp --- a/src/share/vm/gc_implementation/g1/g1MarkSweep.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/g1/g1MarkSweep.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -123,7 +123,7 @@ void G1MarkSweep::mark_sweep_phase1(bool& marked_for_unloading, bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - GCTraceTime tm("phase 1", G1Log::fine() && Verbose, true, gc_timer()); + GCTraceTime tm("phase 1", G1Log::fine() && Verbose, true, gc_timer(), gc_tracer()->gc_id()); GenMarkSweep::trace(" 1"); SharedHeap* sh = SharedHeap::heap(); @@ -148,7 +148,8 @@ &GenMarkSweep::keep_alive, &GenMarkSweep::follow_stack_closure, NULL, - gc_timer()); + gc_timer(), + gc_tracer()->gc_id()); gc_tracer()->report_gc_reference_stats(stats); @@ -262,7 +263,7 @@ G1CollectedHeap* g1h = G1CollectedHeap::heap(); - GCTraceTime tm("phase 2", G1Log::fine() && Verbose, true, gc_timer()); + GCTraceTime tm("phase 2", G1Log::fine() && Verbose, true, gc_timer(), gc_tracer()->gc_id()); GenMarkSweep::trace("2"); // find the first region @@ -299,7 +300,7 @@ G1CollectedHeap* g1h = G1CollectedHeap::heap(); // Adjust the pointers to reflect the new locations - GCTraceTime tm("phase 3", G1Log::fine() && Verbose, true, gc_timer()); + GCTraceTime tm("phase 3", G1Log::fine() && Verbose, true, gc_timer(), gc_tracer()->gc_id()); GenMarkSweep::trace("3"); SharedHeap* sh = SharedHeap::heap(); @@ -362,7 +363,7 @@ // to use a higher index (saved from phase2) when verifying perm_gen. G1CollectedHeap* g1h = G1CollectedHeap::heap(); - GCTraceTime tm("phase 4", G1Log::fine() && Verbose, true, gc_timer()); + GCTraceTime tm("phase 4", G1Log::fine() && Verbose, true, gc_timer(), gc_tracer()->gc_id()); GenMarkSweep::trace("4"); G1SpaceCompactClosure blk; diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/g1/vm_operations_g1.cpp --- a/src/share/vm/gc_implementation/g1/vm_operations_g1.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/g1/vm_operations_g1.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -226,7 +226,7 @@ void VM_CGC_Operation::doit() { gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); - GCTraceTime t(_printGCMessage, G1Log::fine(), true, G1CollectedHeap::heap()->gc_timer_cm()); + GCTraceTime t(_printGCMessage, G1Log::fine(), true, G1CollectedHeap::heap()->gc_timer_cm(), G1CollectedHeap::heap()->concurrent_mark()->concurrent_gc_id()); SharedHeap* sh = SharedHeap::heap(); // This could go away if CollectedHeap gave access to _gc_is_active... if (sh != NULL) { diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/parNew/parNewGeneration.cpp --- a/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -957,7 +957,7 @@ size_policy->minor_collection_begin(); } - GCTraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, NULL); + GCTraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, NULL, gc_tracer.gc_id()); // Capture heap used before collection (for printing). size_t gch_prev_used = gch->used(); @@ -1015,14 +1015,14 @@ ParNewRefProcTaskExecutor task_executor(*this, thread_state_set); stats = rp->process_discovered_references(&is_alive, &keep_alive, &evacuate_followers, &task_executor, - _gc_timer); + _gc_timer, gc_tracer.gc_id()); } else { thread_state_set.flush(); gch->set_par_threads(0); // 0 ==> non-parallel. gch->save_marks(); stats = rp->process_discovered_references(&is_alive, &keep_alive, &evacuate_followers, NULL, - _gc_timer); + _gc_timer, gc_tracer.gc_id()); } gc_tracer.report_gc_reference_stats(stats); if (!promotion_failed()) { diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/parallelScavenge/pcTasks.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/pcTasks.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/parallelScavenge/pcTasks.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -53,7 +53,7 @@ ResourceMark rm; NOT_PRODUCT(GCTraceTime tm("ThreadRootsMarkingTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); @@ -82,7 +82,7 @@ assert(Universe::heap()->is_gc_active(), "called outside gc"); NOT_PRODUCT(GCTraceTime tm("MarkFromRootsTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); PSParallelCompact::MarkAndPushClosure mark_and_push_closure(cm); @@ -153,7 +153,7 @@ assert(Universe::heap()->is_gc_active(), "called outside gc"); NOT_PRODUCT(GCTraceTime tm("RefProcTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); PSParallelCompact::MarkAndPushClosure mark_and_push_closure(cm); @@ -209,7 +209,7 @@ assert(Universe::heap()->is_gc_active(), "called outside gc"); NOT_PRODUCT(GCTraceTime tm("StealMarkingTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); @@ -242,7 +242,7 @@ assert(Universe::heap()->is_gc_active(), "called outside gc"); NOT_PRODUCT(GCTraceTime tm("StealRegionCompactionTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); @@ -309,7 +309,7 @@ void UpdateDensePrefixTask::do_it(GCTaskManager* manager, uint which) { NOT_PRODUCT(GCTraceTime tm("UpdateDensePrefixTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); @@ -324,7 +324,7 @@ assert(Universe::heap()->is_gc_active(), "called outside gc"); NOT_PRODUCT(GCTraceTime tm("DrainStacksCompactionTask", - PrintGCDetails && TraceParallelOldGCTasks, true, NULL)); + PrintGCDetails && TraceParallelOldGCTasks, true, NULL, PSParallelCompact::gc_tracer()->gc_id())); ParCompactionManager* cm = ParCompactionManager::gc_thread_compaction_manager(which); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -169,7 +169,7 @@ gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - GCTraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, NULL); + GCTraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, NULL, _gc_tracer->gc_id()); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(true /* Full GC */,gc_cause); @@ -513,7 +513,7 @@ void PSMarkSweep::mark_sweep_phase1(bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - GCTraceTime tm("phase 1", PrintGCDetails && Verbose, true, _gc_timer); + GCTraceTime tm("phase 1", PrintGCDetails && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace(" 1"); ParallelScavengeHeap* heap = (ParallelScavengeHeap*)Universe::heap(); @@ -548,7 +548,7 @@ ref_processor()->setup_policy(clear_all_softrefs); const ReferenceProcessorStats& stats = ref_processor()->process_discovered_references( - is_alive_closure(), mark_and_push_closure(), follow_stack_closure(), NULL, _gc_timer); + is_alive_closure(), mark_and_push_closure(), follow_stack_closure(), NULL, _gc_timer, _gc_tracer->gc_id()); gc_tracer()->report_gc_reference_stats(stats); } @@ -574,7 +574,7 @@ void PSMarkSweep::mark_sweep_phase2() { - GCTraceTime tm("phase 2", PrintGCDetails && Verbose, true, _gc_timer); + GCTraceTime tm("phase 2", PrintGCDetails && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace("2"); // Now all live objects are marked, compute the new object addresses. @@ -604,7 +604,7 @@ void PSMarkSweep::mark_sweep_phase3() { // Adjust the pointers to reflect the new locations - GCTraceTime tm("phase 3", PrintGCDetails && Verbose, true, _gc_timer); + GCTraceTime tm("phase 3", PrintGCDetails && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace("3"); ParallelScavengeHeap* heap = (ParallelScavengeHeap*)Universe::heap(); @@ -647,7 +647,7 @@ void PSMarkSweep::mark_sweep_phase4() { EventMark m("4 compact heap"); - GCTraceTime tm("phase 4", PrintGCDetails && Verbose, true, _gc_timer); + GCTraceTime tm("phase 4", PrintGCDetails && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace("4"); // All pointers are now adjusted, move objects accordingly diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -978,7 +978,7 @@ // at each young gen gc. Do the update unconditionally (even though a // promotion failure does not swap spaces) because an unknown number of minor // collections will have swapped the spaces an unknown number of times. - GCTraceTime tm("pre compact", print_phases(), true, &_gc_timer); + GCTraceTime tm("pre compact", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ParallelScavengeHeap* heap = gc_heap(); _space_info[from_space_id].set_space(heap->young_gen()->from_space()); _space_info[to_space_id].set_space(heap->young_gen()->to_space()); @@ -1021,7 +1021,7 @@ void PSParallelCompact::post_compact() { - GCTraceTime tm("post compact", print_phases(), true, &_gc_timer); + GCTraceTime tm("post compact", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); for (unsigned int id = old_space_id; id < last_space_id; ++id) { // Clear the marking bitmap, summary data and split info. @@ -1847,7 +1847,7 @@ void PSParallelCompact::summary_phase(ParCompactionManager* cm, bool maximum_compaction) { - GCTraceTime tm("summary phase", print_phases(), true, &_gc_timer); + GCTraceTime tm("summary phase", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); // trace("2"); #ifdef ASSERT @@ -2056,7 +2056,7 @@ gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - GCTraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, NULL); + GCTraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, NULL, _gc_tracer.gc_id()); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(true /* Full GC */,gc_cause); @@ -2351,7 +2351,7 @@ bool maximum_heap_compaction, ParallelOldTracer *gc_tracer) { // Recursively traverse all live objects and mark them - GCTraceTime tm("marking phase", print_phases(), true, &_gc_timer); + GCTraceTime tm("marking phase", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ParallelScavengeHeap* heap = gc_heap(); uint parallel_gc_threads = heap->gc_task_manager()->workers(); @@ -2366,7 +2366,7 @@ ClassLoaderDataGraph::clear_claimed_marks(); { - GCTraceTime tm_m("par mark", print_phases(), true, &_gc_timer); + GCTraceTime tm_m("par mark", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ParallelScavengeHeap::ParStrongRootsScope psrs; @@ -2395,24 +2395,24 @@ // Process reference objects found during marking { - GCTraceTime tm_r("reference processing", print_phases(), true, &_gc_timer); + GCTraceTime tm_r("reference processing", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ReferenceProcessorStats stats; if (ref_processor()->processing_is_mt()) { RefProcTaskExecutor task_executor; stats = ref_processor()->process_discovered_references( is_alive_closure(), &mark_and_push_closure, &follow_stack_closure, - &task_executor, &_gc_timer); + &task_executor, &_gc_timer, _gc_tracer.gc_id()); } else { stats = ref_processor()->process_discovered_references( is_alive_closure(), &mark_and_push_closure, &follow_stack_closure, NULL, - &_gc_timer); + &_gc_timer, _gc_tracer.gc_id()); } gc_tracer->report_gc_reference_stats(stats); } - GCTraceTime tm_c("class unloading", print_phases(), true, &_gc_timer); + GCTraceTime tm_c("class unloading", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); // This is the point where the entire marking should have completed. assert(cm->marking_stacks_empty(), "Marking should have completed"); @@ -2451,7 +2451,7 @@ void PSParallelCompact::adjust_roots() { // Adjust the pointers to reflect the new locations - GCTraceTime tm("adjust roots", print_phases(), true, &_gc_timer); + GCTraceTime tm("adjust roots", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); // Need new claim bits when tracing through and adjusting pointers. ClassLoaderDataGraph::clear_claimed_marks(); @@ -2487,7 +2487,7 @@ void PSParallelCompact::enqueue_region_draining_tasks(GCTaskQueue* q, uint parallel_gc_threads) { - GCTraceTime tm("drain task setup", print_phases(), true, &_gc_timer); + GCTraceTime tm("drain task setup", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); // Find the threads that are active unsigned int which = 0; @@ -2561,7 +2561,7 @@ void PSParallelCompact::enqueue_dense_prefix_tasks(GCTaskQueue* q, uint parallel_gc_threads) { - GCTraceTime tm("dense prefix task setup", print_phases(), true, &_gc_timer); + GCTraceTime tm("dense prefix task setup", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ParallelCompactData& sd = PSParallelCompact::summary_data(); @@ -2643,7 +2643,7 @@ GCTaskQueue* q, ParallelTaskTerminator* terminator_ptr, uint parallel_gc_threads) { - GCTraceTime tm("steal task setup", print_phases(), true, &_gc_timer); + GCTraceTime tm("steal task setup", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); // Once a thread has drained it's stack, it should try to steal regions from // other threads. @@ -2691,7 +2691,7 @@ void PSParallelCompact::compact() { // trace("5"); - GCTraceTime tm("compaction phase", print_phases(), true, &_gc_timer); + GCTraceTime tm("compaction phase", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ParallelScavengeHeap* heap = (ParallelScavengeHeap*)Universe::heap(); assert(heap->kind() == CollectedHeap::ParallelScavengeHeap, "Sanity"); @@ -2708,7 +2708,7 @@ enqueue_region_stealing_tasks(q, &terminator, active_gc_threads); { - GCTraceTime tm_pc("par compact", print_phases(), true, &_gc_timer); + GCTraceTime tm_pc("par compact", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); gc_task_manager()->execute_and_wait(q); @@ -2722,7 +2722,7 @@ { // Update the deferred objects, if any. Any compaction manager can be used. - GCTraceTime tm_du("deferred updates", print_phases(), true, &_gc_timer); + GCTraceTime tm_du("deferred updates", print_phases(), true, &_gc_timer, _gc_tracer.gc_id()); ParCompactionManager* cm = ParCompactionManager::manager_array(0); for (unsigned int id = old_space_id; id < last_space_id; ++id) { update_deferred_objects(cm, SpaceId(id)); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.hpp --- a/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -1004,6 +1004,10 @@ static bool _dwl_initialized; #endif // #ifdef ASSERT + + public: + static ParallelOldTracer* gc_tracer() { return &_gc_tracer; } + private: static void initialize_space_info(); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -331,7 +331,7 @@ gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - GCTraceTime t1(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, NULL); + GCTraceTime t1(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, NULL, _gc_tracer.gc_id()); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(false /* not full GC */,gc_cause); @@ -397,7 +397,7 @@ // We'll use the promotion manager again later. PSPromotionManager* promotion_manager = PSPromotionManager::vm_thread_promotion_manager(); { - GCTraceTime tm("Scavenge", false, false, &_gc_timer); + GCTraceTime tm("Scavenge", false, false, &_gc_timer, _gc_tracer.gc_id()); ParallelScavengeHeap::ParStrongRootsScope psrs; GCTaskQueue* q = GCTaskQueue::create(); @@ -439,7 +439,7 @@ // Process reference objects discovered during scavenge { - GCTraceTime tm("References", false, false, &_gc_timer); + GCTraceTime tm("References", false, false, &_gc_timer, _gc_tracer.gc_id()); reference_processor()->setup_policy(false); // not always_clear reference_processor()->set_active_mt_degree(active_workers); @@ -450,10 +450,10 @@ PSRefProcTaskExecutor task_executor; stats = reference_processor()->process_discovered_references( &_is_alive_closure, &keep_alive, &evac_followers, &task_executor, - &_gc_timer); + &_gc_timer, _gc_tracer.gc_id()); } else { stats = reference_processor()->process_discovered_references( - &_is_alive_closure, &keep_alive, &evac_followers, NULL, &_gc_timer); + &_is_alive_closure, &keep_alive, &evac_followers, NULL, &_gc_timer, _gc_tracer.gc_id()); } _gc_tracer.report_gc_reference_stats(stats); @@ -468,7 +468,7 @@ } { - GCTraceTime tm("StringTable", false, false, &_gc_timer); + GCTraceTime tm("StringTable", false, false, &_gc_timer, _gc_tracer.gc_id()); // Unlink any dead interned Strings and process the remaining live ones. PSScavengeRootsClosure root_closure(promotion_manager); StringTable::unlink_or_oops_do(&_is_alive_closure, &root_closure); @@ -638,7 +638,7 @@ NOT_PRODUCT(reference_processor()->verify_no_references_recorded()); { - GCTraceTime tm("Prune Scavenge Root Methods", false, false, &_gc_timer); + GCTraceTime tm("Prune Scavenge Root Methods", false, false, &_gc_timer, _gc_tracer.gc_id()); CodeCache::prune_scavenge_root_nmethods(); } diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcId.cpp --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/src/share/vm/gc_implementation/shared/gcId.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -0,0 +1,42 @@ +/* + * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + * + */ + +#include "precompiled.hpp" +#include "gc_implementation/shared/gcId.hpp" +#include "runtime/safepoint.hpp" + +uint GCId::_next_id = 0; + +const GCId GCId::create() { + return GCId(_next_id++); +} +const GCId GCId::peek() { + return GCId(_next_id); +} +const GCId GCId::undefined() { + return GCId(UNDEFINED); +} +bool GCId::is_undefined() const { + return _id == UNDEFINED; +} diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcId.hpp --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/src/share/vm/gc_implementation/shared/gcId.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -0,0 +1,51 @@ +/* + * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + * + */ + +#ifndef SHARE_VM_GC_IMPLEMENTATION_SHARED_GCID_HPP +#define SHARE_VM_GC_IMPLEMENTATION_SHARED_GCID_HPP + +#include "memory/allocation.hpp" + +class GCId VALUE_OBJ_CLASS_SPEC { + private: + uint _id; + GCId(uint id) : _id(id) {} + GCId() { } // Unused + + static uint _next_id; + static const uint UNDEFINED = (uint)-1; + + public: + uint id() const { + assert(_id != UNDEFINED, "Using undefined GC ID"); + return _id; + } + bool is_undefined() const; + + static const GCId create(); + static const GCId peek(); + static const GCId undefined(); +}; + +#endif // SHARE_VM_GC_IMPLEMENTATION_SHARED_GCID_HPP diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcTrace.cpp --- a/src/share/vm/gc_implementation/shared/gcTrace.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/shared/gcTrace.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -25,6 +25,7 @@ #include "precompiled.hpp" #include "gc_implementation/shared/copyFailedInfo.hpp" #include "gc_implementation/shared/gcHeapSummary.hpp" +#include "gc_implementation/shared/gcId.hpp" #include "gc_implementation/shared/gcTimer.hpp" #include "gc_implementation/shared/gcTrace.hpp" #include "gc_implementation/shared/objectCountEventSender.hpp" @@ -38,19 +39,14 @@ #include "gc_implementation/g1/evacuationInfo.hpp" #endif -#define assert_unset_gc_id() assert(_shared_gc_info.id() == SharedGCInfo::UNSET_GCID, "GC already started?") -#define assert_set_gc_id() assert(_shared_gc_info.id() != SharedGCInfo::UNSET_GCID, "GC not started?") - -static GCId GCTracer_next_gc_id = 0; -static GCId create_new_gc_id() { - return GCTracer_next_gc_id++; -} +#define assert_unset_gc_id() assert(_shared_gc_info.gc_id().is_undefined(), "GC already started?") +#define assert_set_gc_id() assert(!_shared_gc_info.gc_id().is_undefined(), "GC not started?") void GCTracer::report_gc_start_impl(GCCause::Cause cause, const Ticks& timestamp) { assert_unset_gc_id(); - GCId gc_id = create_new_gc_id(); - _shared_gc_info.set_id(gc_id); + GCId gc_id = GCId::create(); + _shared_gc_info.set_gc_id(gc_id); _shared_gc_info.set_cause(cause); _shared_gc_info.set_start_timestamp(timestamp); } @@ -62,7 +58,7 @@ } bool GCTracer::has_reported_gc_start() const { - return _shared_gc_info.id() != SharedGCInfo::UNSET_GCID; + return !_shared_gc_info.gc_id().is_undefined(); } void GCTracer::report_gc_end_impl(const Ticks& timestamp, TimePartitions* time_partitions) { @@ -81,7 +77,7 @@ report_gc_end_impl(timestamp, time_partitions); - _shared_gc_info.set_id(SharedGCInfo::UNSET_GCID); + _shared_gc_info.set_gc_id(GCId::undefined()); } void GCTracer::report_gc_reference_stats(const ReferenceProcessorStats& rps) const { @@ -132,7 +128,7 @@ if (!cit.allocation_failed()) { HeapInspection hi(false, false, false, NULL); hi.populate_table(&cit, is_alive_cl); - ObjectCountEventSenderClosure event_sender(_shared_gc_info.id(), cit.size_of_instances_in_words(), Ticks::now()); + ObjectCountEventSenderClosure event_sender(_shared_gc_info.gc_id(), cit.size_of_instances_in_words(), Ticks::now()); cit.iterate(&event_sender); } } diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcTrace.hpp --- a/src/share/vm/gc_implementation/shared/gcTrace.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/shared/gcTrace.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -27,6 +27,7 @@ #include "gc_interface/gcCause.hpp" #include "gc_interface/gcName.hpp" +#include "gc_implementation/shared/gcId.hpp" #include "gc_implementation/shared/gcWhen.hpp" #include "gc_implementation/shared/copyFailedInfo.hpp" #include "memory/allocation.hpp" @@ -38,7 +39,6 @@ #include "utilities/macros.hpp" #include "utilities/ticks.hpp" -typedef uint GCId; class EvacuationInfo; class GCHeapSummary; @@ -50,11 +50,8 @@ class BoolObjectClosure; class SharedGCInfo VALUE_OBJ_CLASS_SPEC { - public: - static const GCId UNSET_GCID = (GCId)-1; - private: - GCId _id; + GCId _gc_id; GCName _name; GCCause::Cause _cause; Ticks _start_timestamp; @@ -64,7 +61,7 @@ public: SharedGCInfo(GCName name) : - _id(UNSET_GCID), + _gc_id(GCId::undefined()), _name(name), _cause(GCCause::_last_gc_cause), _start_timestamp(), @@ -73,8 +70,8 @@ _longest_pause() { } - void set_id(GCId id) { _id = id; } - GCId id() const { return _id; } + void set_gc_id(GCId gc_id) { _gc_id = gc_id; } + const GCId& gc_id() const { return _gc_id; } void set_start_timestamp(const Ticks& timestamp) { _start_timestamp = timestamp; } const Ticks start_timestamp() const { return _start_timestamp; } @@ -131,10 +128,11 @@ void report_gc_reference_stats(const ReferenceProcessorStats& rp) const; void report_object_count_after_gc(BoolObjectClosure* object_filter) NOT_SERVICES_RETURN; bool has_reported_gc_start() const; + const GCId& gc_id() { return _shared_gc_info.gc_id(); } protected: GCTracer(GCName name) : _shared_gc_info(name) {} - virtual void report_gc_start_impl(GCCause::Cause cause, const Ticks& timestamp); + void report_gc_start_impl(GCCause::Cause cause, const Ticks& timestamp); virtual void report_gc_end_impl(const Ticks& timestamp, TimePartitions* time_partitions); private: diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcTraceSend.cpp --- a/src/share/vm/gc_implementation/shared/gcTraceSend.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/shared/gcTraceSend.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -43,7 +43,7 @@ void GCTracer::send_garbage_collection_event() const { EventGCGarbageCollection event(UNTIMED); if (event.should_commit()) { - event.set_gcId(_shared_gc_info.id()); + event.set_gcId(_shared_gc_info.gc_id().id()); event.set_name(_shared_gc_info.name()); event.set_cause((u2) _shared_gc_info.cause()); event.set_sumOfPauses(_shared_gc_info.sum_of_pauses()); @@ -57,7 +57,7 @@ void GCTracer::send_reference_stats_event(ReferenceType type, size_t count) const { EventGCReferenceStatistics e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_type((u1)type); e.set_count(count); e.commit(); @@ -68,7 +68,7 @@ const MetaspaceChunkFreeListSummary& summary) const { EventMetaspaceChunkFreeListSummary e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_when(when); e.set_metadataType(mdtype); @@ -91,7 +91,7 @@ void ParallelOldTracer::send_parallel_old_event() const { EventGCParallelOld e(UNTIMED); if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_densePrefix((TraceAddress)_parallel_old_gc_info.dense_prefix()); e.set_starttime(_shared_gc_info.start_timestamp()); e.set_endtime(_shared_gc_info.end_timestamp()); @@ -102,7 +102,7 @@ void YoungGCTracer::send_young_gc_event() const { EventGCYoungGarbageCollection e(UNTIMED); if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_tenuringThreshold(_tenuring_threshold); e.set_starttime(_shared_gc_info.start_timestamp()); e.set_endtime(_shared_gc_info.end_timestamp()); @@ -113,7 +113,7 @@ void OldGCTracer::send_old_gc_event() const { EventGCOldGarbageCollection e(UNTIMED); if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_starttime(_shared_gc_info.start_timestamp()); e.set_endtime(_shared_gc_info.end_timestamp()); e.commit(); @@ -132,7 +132,7 @@ void YoungGCTracer::send_promotion_failed_event(const PromotionFailedInfo& pf_info) const { EventPromotionFailed e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_data(to_trace_struct(pf_info)); e.set_thread(pf_info.thread()->thread_id()); e.commit(); @@ -143,7 +143,7 @@ void OldGCTracer::send_concurrent_mode_failure_event() { EventConcurrentModeFailure e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.commit(); } } @@ -152,7 +152,7 @@ void G1NewTracer::send_g1_young_gc_event() { EventGCG1GarbageCollection e(UNTIMED); if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_type(_g1_young_gc_info.type()); e.set_starttime(_shared_gc_info.start_timestamp()); e.set_endtime(_shared_gc_info.end_timestamp()); @@ -163,7 +163,7 @@ void G1NewTracer::send_evacuation_info_event(EvacuationInfo* info) { EventEvacuationInfo e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_cSetRegions(info->collectionset_regions()); e.set_cSetUsedBefore(info->collectionset_used_before()); e.set_cSetUsedAfter(info->collectionset_used_after()); @@ -179,7 +179,7 @@ void G1NewTracer::send_evacuation_failed_event(const EvacuationFailedInfo& ef_info) const { EventEvacuationFailed e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_data(to_trace_struct(ef_info)); e.commit(); } @@ -206,17 +206,17 @@ } class GCHeapSummaryEventSender : public GCHeapSummaryVisitor { - GCId _id; + GCId _gc_id; GCWhen::Type _when; public: - GCHeapSummaryEventSender(GCId id, GCWhen::Type when) : _id(id), _when(when) {} + GCHeapSummaryEventSender(GCId gc_id, GCWhen::Type when) : _gc_id(gc_id), _when(when) {} void visit(const GCHeapSummary* heap_summary) const { const VirtualSpaceSummary& heap_space = heap_summary->heap(); EventGCHeapSummary e; if (e.should_commit()) { - e.set_gcId(_id); + e.set_gcId(_gc_id.id()); e.set_when((u1)_when); e.set_heapSpace(to_trace_struct(heap_space)); e.set_heapUsed(heap_summary->used()); @@ -236,7 +236,7 @@ EventPSHeapSummary e; if (e.should_commit()) { - e.set_gcId(_id); + e.set_gcId(_gc_id.id()); e.set_when((u1)_when); e.set_oldSpace(to_trace_struct(ps_heap_summary->old())); @@ -251,7 +251,7 @@ }; void GCTracer::send_gc_heap_summary_event(GCWhen::Type when, const GCHeapSummary& heap_summary) const { - GCHeapSummaryEventSender visitor(_shared_gc_info.id(), when); + GCHeapSummaryEventSender visitor(_shared_gc_info.gc_id(), when); heap_summary.accept(&visitor); } @@ -268,7 +268,7 @@ void GCTracer::send_meta_space_summary_event(GCWhen::Type when, const MetaspaceSummary& meta_space_summary) const { EventMetaspaceSummary e; if (e.should_commit()) { - e.set_gcId(_shared_gc_info.id()); + e.set_gcId(_shared_gc_info.gc_id().id()); e.set_when((u1) when); e.set_gcThreshold(meta_space_summary.capacity_until_GC()); e.set_metaspace(to_trace_struct(meta_space_summary.meta_space())); @@ -287,7 +287,7 @@ void send_phase(PausePhase* pause) { T event(UNTIMED); if (event.should_commit()) { - event.set_gcId(_gc_id); + event.set_gcId(_gc_id.id()); event.set_name(pause->name()); event.set_starttime(pause->start()); event.set_endtime(pause->end()); @@ -311,7 +311,7 @@ }; void GCTracer::send_phase_events(TimePartitions* time_partitions) const { - PhaseSender phase_reporter(_shared_gc_info.id()); + PhaseSender phase_reporter(_shared_gc_info.gc_id()); TimePartitionPhasesIterator iter(time_partitions); while (iter.has_next()) { diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcTraceTime.cpp --- a/src/share/vm/gc_implementation/shared/gcTraceTime.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/shared/gcTraceTime.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -24,6 +24,7 @@ #include "precompiled.hpp" #include "gc_implementation/shared/gcTimer.hpp" +#include "gc_implementation/shared/gcTrace.hpp" #include "gc_implementation/shared/gcTraceTime.hpp" #include "runtime/globals.hpp" #include "runtime/os.hpp" @@ -34,7 +35,7 @@ #include "utilities/ticks.inline.hpp" -GCTraceTime::GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer) : +GCTraceTime::GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id) : _title(title), _doit(doit), _print_cr(print_cr), _timer(timer), _start_counter() { if (_doit || _timer != NULL) { _start_counter.stamp(); @@ -52,6 +53,9 @@ gclog_or_tty->stamp(); gclog_or_tty->print(": "); } + if (PrintGCID) { + gclog_or_tty->print("#%u: ", gc_id.id()); + } gclog_or_tty->print("[%s", title); gclog_or_tty->flush(); } diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/gcTraceTime.hpp --- a/src/share/vm/gc_implementation/shared/gcTraceTime.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/shared/gcTraceTime.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -25,6 +25,7 @@ #ifndef SHARE_VM_GC_IMPLEMENTATION_SHARED_GCTRACETIME_HPP #define SHARE_VM_GC_IMPLEMENTATION_SHARED_GCTRACETIME_HPP +#include "gc_implementation/shared/gcTrace.hpp" #include "prims/jni_md.h" #include "utilities/ticks.hpp" @@ -38,7 +39,7 @@ Ticks _start_counter; public: - GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer); + GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id); ~GCTraceTime(); }; diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_implementation/shared/objectCountEventSender.cpp --- a/src/share/vm/gc_implementation/shared/objectCountEventSender.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_implementation/shared/objectCountEventSender.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -24,6 +24,7 @@ #include "precompiled.hpp" +#include "gc_implementation/shared/gcId.hpp" #include "gc_implementation/shared/objectCountEventSender.hpp" #include "memory/heapInspection.hpp" #include "trace/tracing.hpp" @@ -38,7 +39,7 @@ "Only call this method if the event is enabled"); EventObjectCountAfterGC event(UNTIMED); - event.set_gcId(gc_id); + event.set_gcId(gc_id.id()); event.set_class(entry->klass()); event.set_count(entry->count()); event.set_totalSize(entry->words() * BytesPerWord); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/gc_interface/collectedHeap.cpp --- a/src/share/vm/gc_interface/collectedHeap.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/gc_interface/collectedHeap.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -558,13 +558,13 @@ void CollectedHeap::pre_full_gc_dump(GCTimer* timer) { if (HeapDumpBeforeFullGC) { - GCTraceTime tt("Heap Dump (before full gc): ", PrintGCDetails, false, timer); + GCTraceTime tt("Heap Dump (before full gc): ", PrintGCDetails, false, timer, GCId::create()); // We are doing a "major" collection and a heap dump before // major collection has been requested. HeapDumper::dump_heap(); } if (PrintClassHistogramBeforeFullGC) { - GCTraceTime tt("Class Histogram (before full gc): ", PrintGCDetails, true, timer); + GCTraceTime tt("Class Histogram (before full gc): ", PrintGCDetails, true, timer, GCId::create()); VM_GC_HeapInspection inspector(gclog_or_tty, false /* ! full gc */); inspector.doit(); } @@ -572,11 +572,11 @@ void CollectedHeap::post_full_gc_dump(GCTimer* timer) { if (HeapDumpAfterFullGC) { - GCTraceTime tt("Heap Dump (after full gc): ", PrintGCDetails, false, timer); + GCTraceTime tt("Heap Dump (after full gc): ", PrintGCDetails, false, timer, GCId::create()); HeapDumper::dump_heap(); } if (PrintClassHistogramAfterFullGC) { - GCTraceTime tt("Class Histogram (after full gc): ", PrintGCDetails, true, timer); + GCTraceTime tt("Class Histogram (after full gc): ", PrintGCDetails, true, timer, GCId::create()); VM_GC_HeapInspection inspector(gclog_or_tty, false /* ! full gc */); inspector.doit(); } diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/memory/defNewGeneration.cpp --- a/src/share/vm/memory/defNewGeneration.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/memory/defNewGeneration.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -584,7 +584,7 @@ init_assuming_no_promotion_failure(); - GCTraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, NULL); + GCTraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, NULL, gc_tracer.gc_id()); // Capture heap used before collection (for printing). size_t gch_prev_used = gch->used(); @@ -642,7 +642,7 @@ rp->setup_policy(clear_all_soft_refs); const ReferenceProcessorStats& stats = rp->process_discovered_references(&is_alive, &keep_alive, &evacuate_followers, - NULL, _gc_timer); + NULL, _gc_timer, gc_tracer.gc_id()); gc_tracer.report_gc_reference_stats(stats); if (!_promotion_failed) { diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/memory/genCollectedHeap.cpp --- a/src/share/vm/memory/genCollectedHeap.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/memory/genCollectedHeap.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -28,6 +28,7 @@ #include "classfile/vmSymbols.hpp" #include "code/icBuffer.hpp" #include "gc_implementation/shared/collectorCounters.hpp" +#include "gc_implementation/shared/gcTrace.hpp" #include "gc_implementation/shared/gcTraceTime.hpp" #include "gc_implementation/shared/vmGCOperations.hpp" #include "gc_interface/collectedHeap.inline.hpp" @@ -385,7 +386,9 @@ const char* gc_cause_prefix = complete ? "Full GC" : "GC"; gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - GCTraceTime t(GCCauseString(gc_cause_prefix, gc_cause()), PrintGCDetails, false, NULL); + // The PrintGCDetails logging starts before we have incremented the GC id. We will do that later + // so we can assume here that the next GC id is what we want. + GCTraceTime t(GCCauseString(gc_cause_prefix, gc_cause()), PrintGCDetails, false, NULL, GCId::peek()); gc_prologue(complete); increment_total_collections(complete); @@ -418,7 +421,9 @@ } // Timer for individual generations. Last argument is false: no CR // FIXME: We should try to start the timing earlier to cover more of the GC pause - GCTraceTime t1(_gens[i]->short_name(), PrintGCDetails, false, NULL); + // The PrintGCDetails logging starts before we have incremented the GC id. We will do that later + // so we can assume here that the next GC id is what we want. + GCTraceTime t1(_gens[i]->short_name(), PrintGCDetails, false, NULL, GCId::peek()); TraceCollectorStats tcs(_gens[i]->counters()); TraceMemoryManagerStats tmms(_gens[i]->kind(),gc_cause()); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/memory/genMarkSweep.cpp --- a/src/share/vm/memory/genMarkSweep.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/memory/genMarkSweep.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -69,7 +69,7 @@ _ref_processor = rp; rp->setup_policy(clear_all_softrefs); - GCTraceTime t1(GCCauseString("Full GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, NULL); + GCTraceTime t1(GCCauseString("Full GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, NULL, _gc_tracer->gc_id()); gch->trace_heap_before_gc(_gc_tracer); @@ -193,7 +193,7 @@ void GenMarkSweep::mark_sweep_phase1(int level, bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - GCTraceTime tm("phase 1", PrintGC && Verbose, true, _gc_timer); + GCTraceTime tm("phase 1", PrintGC && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace(" 1"); GenCollectedHeap* gch = GenCollectedHeap::heap(); @@ -222,7 +222,7 @@ ref_processor()->setup_policy(clear_all_softrefs); const ReferenceProcessorStats& stats = ref_processor()->process_discovered_references( - &is_alive, &keep_alive, &follow_stack_closure, NULL, _gc_timer); + &is_alive, &keep_alive, &follow_stack_closure, NULL, _gc_timer, _gc_tracer->gc_id()); gc_tracer()->report_gc_reference_stats(stats); } @@ -264,7 +264,7 @@ GenCollectedHeap* gch = GenCollectedHeap::heap(); - GCTraceTime tm("phase 2", PrintGC && Verbose, true, _gc_timer); + GCTraceTime tm("phase 2", PrintGC && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace("2"); gch->prepare_for_compaction(); @@ -281,7 +281,7 @@ GenCollectedHeap* gch = GenCollectedHeap::heap(); // Adjust the pointers to reflect the new locations - GCTraceTime tm("phase 3", PrintGC && Verbose, true, _gc_timer); + GCTraceTime tm("phase 3", PrintGC && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace("3"); // Need new claim bits for the pointer adjustment tracing. @@ -336,7 +336,7 @@ // to use a higher index (saved from phase2) when verifying perm_gen. GenCollectedHeap* gch = GenCollectedHeap::heap(); - GCTraceTime tm("phase 4", PrintGC && Verbose, true, _gc_timer); + GCTraceTime tm("phase 4", PrintGC && Verbose, true, _gc_timer, _gc_tracer->gc_id()); trace("4"); GenCompactClosure blk; diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/memory/referenceProcessor.cpp --- a/src/share/vm/memory/referenceProcessor.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/memory/referenceProcessor.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -190,7 +190,8 @@ OopClosure* keep_alive, VoidClosure* complete_gc, AbstractRefProcTaskExecutor* task_executor, - GCTimer* gc_timer) { + GCTimer* gc_timer, + GCId gc_id) { NOT_PRODUCT(verify_ok_to_handle_reflists()); assert(!enqueuing_is_done(), "If here enqueuing should not be complete"); @@ -212,7 +213,7 @@ // Soft references size_t soft_count = 0; { - GCTraceTime tt("SoftReference", trace_time, false, gc_timer); + GCTraceTime tt("SoftReference", trace_time, false, gc_timer, gc_id); soft_count = process_discovered_reflist(_discoveredSoftRefs, _current_soft_ref_policy, true, is_alive, keep_alive, complete_gc, task_executor); @@ -223,7 +224,7 @@ // Weak references size_t weak_count = 0; { - GCTraceTime tt("WeakReference", trace_time, false, gc_timer); + GCTraceTime tt("WeakReference", trace_time, false, gc_timer, gc_id); weak_count = process_discovered_reflist(_discoveredWeakRefs, NULL, true, is_alive, keep_alive, complete_gc, task_executor); @@ -232,7 +233,7 @@ // Final references size_t final_count = 0; { - GCTraceTime tt("FinalReference", trace_time, false, gc_timer); + GCTraceTime tt("FinalReference", trace_time, false, gc_timer, gc_id); final_count = process_discovered_reflist(_discoveredFinalRefs, NULL, false, is_alive, keep_alive, complete_gc, task_executor); @@ -241,7 +242,7 @@ // Phantom references size_t phantom_count = 0; { - GCTraceTime tt("PhantomReference", trace_time, false, gc_timer); + GCTraceTime tt("PhantomReference", trace_time, false, gc_timer, gc_id); phantom_count = process_discovered_reflist(_discoveredPhantomRefs, NULL, false, is_alive, keep_alive, complete_gc, task_executor); @@ -253,7 +254,7 @@ // thus use JNI weak references to circumvent the phantom references and // resurrect a "post-mortem" object. { - GCTraceTime tt("JNI Weak Reference", trace_time, false, gc_timer); + GCTraceTime tt("JNI Weak Reference", trace_time, false, gc_timer, gc_id); if (task_executor != NULL) { task_executor->set_single_threaded_mode(); } @@ -1251,14 +1252,15 @@ OopClosure* keep_alive, VoidClosure* complete_gc, YieldClosure* yield, - GCTimer* gc_timer) { + GCTimer* gc_timer, + GCId gc_id) { NOT_PRODUCT(verify_ok_to_handle_reflists()); // Soft references { GCTraceTime tt("Preclean SoftReferences", PrintGCDetails && PrintReferenceGC, - false, gc_timer); + false, gc_timer, gc_id); for (uint i = 0; i < _max_num_q; i++) { if (yield->should_return()) { return; @@ -1271,7 +1273,7 @@ // Weak references { GCTraceTime tt("Preclean WeakReferences", PrintGCDetails && PrintReferenceGC, - false, gc_timer); + false, gc_timer, gc_id); for (uint i = 0; i < _max_num_q; i++) { if (yield->should_return()) { return; @@ -1284,7 +1286,7 @@ // Final references { GCTraceTime tt("Preclean FinalReferences", PrintGCDetails && PrintReferenceGC, - false, gc_timer); + false, gc_timer, gc_id); for (uint i = 0; i < _max_num_q; i++) { if (yield->should_return()) { return; @@ -1297,7 +1299,7 @@ // Phantom references { GCTraceTime tt("Preclean PhantomReferences", PrintGCDetails && PrintReferenceGC, - false, gc_timer); + false, gc_timer, gc_id); for (uint i = 0; i < _max_num_q; i++) { if (yield->should_return()) { return; diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/memory/referenceProcessor.hpp --- a/src/share/vm/memory/referenceProcessor.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/memory/referenceProcessor.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -25,6 +25,7 @@ #ifndef SHARE_VM_MEMORY_REFERENCEPROCESSOR_HPP #define SHARE_VM_MEMORY_REFERENCEPROCESSOR_HPP +#include "gc_implementation/shared/gcTrace.hpp" #include "memory/referencePolicy.hpp" #include "memory/referenceProcessorStats.hpp" #include "memory/referenceType.hpp" @@ -349,7 +350,8 @@ OopClosure* keep_alive, VoidClosure* complete_gc, YieldClosure* yield, - GCTimer* gc_timer); + GCTimer* gc_timer, + GCId gc_id); // Delete entries in the discovered lists that have // either a null referent or are not active. Such @@ -480,7 +482,8 @@ OopClosure* keep_alive, VoidClosure* complete_gc, AbstractRefProcTaskExecutor* task_executor, - GCTimer *gc_timer); + GCTimer *gc_timer, + GCId gc_id); // Enqueue references at end of GC (called by the garbage collector) bool enqueue_discovered_references(AbstractRefProcTaskExecutor* task_executor = NULL); diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/runtime/globals.hpp --- a/src/share/vm/runtime/globals.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/runtime/globals.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -2287,6 +2287,9 @@ manageable(bool, PrintGCTimeStamps, false, \ "Print timestamps at garbage collection") \ \ + manageable(bool, PrintGCID, false, \ + "Print an identifier for each garbage collection") \ + \ product(bool, PrintGCTaskTimeStamps, false, \ "Print timestamps for individual gc worker thread tasks") \ \ diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/utilities/ostream.cpp --- a/src/share/vm/utilities/ostream.cpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/utilities/ostream.cpp Thu Jun 19 13:31:14 2014 +0200 @@ -24,6 +24,7 @@ #include "precompiled.hpp" #include "compiler/compileLog.hpp" +#include "gc_implementation/shared/gcId.hpp" #include "oops/oop.inline.hpp" #include "runtime/arguments.hpp" #include "utilities/defaultStream.hpp" @@ -240,6 +241,14 @@ return; } +void outputStream::gclog_stamp(const GCId& gc_id) { + date_stamp(PrintGCDateStamps); + stamp(PrintGCTimeStamps); + if (PrintGCID) { + print("#%u: ", gc_id.id()); + } +} + outputStream& outputStream::indent() { while (_position < _indentation) sp(); return *this; diff -r 5d855d021755 -r 0982ec23da03 src/share/vm/utilities/ostream.hpp --- a/src/share/vm/utilities/ostream.hpp Wed Jun 25 15:51:15 2014 -0700 +++ b/src/share/vm/utilities/ostream.hpp Thu Jun 19 13:31:14 2014 +0200 @@ -28,6 +28,7 @@ #include "memory/allocation.hpp" #include "runtime/timer.hpp" +class GCId; DEBUG_ONLY(class ResourceMark;) // Output streams for printing @@ -107,6 +108,7 @@ void date_stamp(bool guard) { date_stamp(guard, "", ": "); } + void gclog_stamp(const GCId& gc_id); // portable printing of 64 bit integers void print_jlong(jlong value); diff -r 5d855d021755 -r 0982ec23da03 test/gc/logging/TestGCId.java --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/test/gc/logging/TestGCId.java Thu Jun 19 13:31:14 2014 +0200 @@ -0,0 +1,91 @@ +/* + * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +/* + * @test TestGCId + * @bug 8043607 + * @summary Ensure that the GCId is logged + * @key gc + * @library /testlibrary + */ + +import com.oracle.java.testlibrary.ProcessTools; +import com.oracle.java.testlibrary.OutputAnalyzer; + +public class TestGCId { + public static void main(String[] args) throws Exception { + testGCId("UseParallelGC", "PrintGC"); + testGCId("UseParallelGC", "PrintGCDetails"); + + testGCId("UseG1GC", "PrintGC"); + testGCId("UseG1GC", "PrintGCDetails"); + + testGCId("UseConcMarkSweepGC", "PrintGC"); + testGCId("UseConcMarkSweepGC", "PrintGCDetails"); + + testGCId("UseSerialGC", "PrintGC"); + testGCId("UseSerialGC", "PrintGCDetails"); + } + + private static void verifyContainsGCIDs(OutputAnalyzer output) { + output.shouldMatch("^#0: \\["); + output.shouldMatch("^#1: \\["); + output.shouldHaveExitValue(0); + } + + private static void verifyContainsNoGCIDs(OutputAnalyzer output) { + output.shouldNotMatch("^#[0-9]+: \\["); + output.shouldHaveExitValue(0); + } + + private static void testGCId(String gcFlag, String logFlag) throws Exception { + // GCID logging enabled + ProcessBuilder pb_enabled = + ProcessTools.createJavaProcessBuilder("-XX:+" + gcFlag, "-XX:+" + logFlag, "-Xmx10M", "-XX:+PrintGCID", GCTest.class.getName()); + verifyContainsGCIDs(new OutputAnalyzer(pb_enabled.start())); + + // GCID logging disabled + ProcessBuilder pb_disabled = + ProcessTools.createJavaProcessBuilder("-XX:+" + gcFlag, "-XX:+" + logFlag, "-Xmx10M", "-XX:-PrintGCID", GCTest.class.getName()); + verifyContainsNoGCIDs(new OutputAnalyzer(pb_disabled.start())); + + // GCID logging default + ProcessBuilder pb_default = + ProcessTools.createJavaProcessBuilder("-XX:+" + gcFlag, "-XX:+" + logFlag, "-Xmx10M", GCTest.class.getName()); + verifyContainsGCIDs(new OutputAnalyzer(pb_default.start())); + } + + static class GCTest { + private static byte[] garbage; + public static void main(String [] args) { + System.out.println("Creating garbage"); + // create 128MB of garbage. This should result in at least one GC + for (int i = 0; i < 1024; i++) { + garbage = new byte[128 * 1024]; + } + // do a system gc to get one more gc + System.gc(); + System.out.println("Done"); + } + } +}