--- old/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp 2016-03-17 14:11:49.349514846 +0100 +++ new/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp 2016-03-17 14:11:49.217510399 +0100 @@ -1518,7 +1518,7 @@ gch->pre_full_gc_dump(gc_timer); - GCTraceTime(Trace, gc) t("CMS:MSC"); + GCTraceTime(Trace, gc, phases) t("CMS:MSC"); // Temporarily widen the span of the weak reference processing to // the entire heap. @@ -2234,7 +2234,7 @@ }; bool CMSCollector::verify_after_remark() { - GCTraceTime(Info, gc, verify) tm("Verifying CMS Marking."); + GCTraceTime(Info, gc, phases, verify) tm("Verifying CMS Marking."); MutexLockerEx ml(verification_mark_bm()->lock(), Mutex::_no_safepoint_check_flag); static bool init = false; @@ -2818,7 +2818,7 @@ // CMS collection cycle. setup_cms_unloading_and_verification_state(); - GCTraceTime(Trace, gc) ts("checkpointRootsInitialWork", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) ts("checkpointRootsInitialWork", _gc_timer_cm); // Reset all the PLAB chunk arrays if necessary. if (_survivor_plab_array != NULL && !CMSPLABRecordAlways) { @@ -4102,8 +4102,6 @@ // expect it to be false and set to true FlagSetting fl(gch->_is_gc_active, false); - GCTraceTime(Trace, gc) tm("Pause Scavenge Before Remark", _gc_timer_cm); - gch->do_collection(true, // full (i.e. force, see below) false, // !clear_all_soft_refs 0, // size @@ -4121,7 +4119,7 @@ } void CMSCollector::checkpointRootsFinalWork() { - GCTraceTime(Trace, gc) tm("checkpointRootsFinalWork", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) tm("checkpointRootsFinalWork", _gc_timer_cm); assert(haveFreelistLocks(), "must have free list locks"); assert_lock_strong(bitMapLock()); @@ -4171,10 +4169,10 @@ // the most recent young generation GC, minus those cleaned up by the // concurrent precleaning. if (CMSParallelRemarkEnabled) { - GCTraceTime(Debug, gc) t("Rescan (parallel)", _gc_timer_cm); + GCTraceTime(Debug, gc, phases) t("Rescan (parallel)", _gc_timer_cm); do_remark_parallel(); } else { - GCTraceTime(Debug, gc) t("Rescan (non-parallel)", _gc_timer_cm); + GCTraceTime(Debug, gc, phases) t("Rescan (non-parallel)", _gc_timer_cm); do_remark_non_parallel(); } } @@ -4182,7 +4180,7 @@ verify_overflow_empty(); { - GCTraceTime(Trace, gc) ts("refProcessingWork", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) ts("refProcessingWork", _gc_timer_cm); refProcessingWork(); } verify_work_stacks_empty(); @@ -4905,7 +4903,7 @@ NULL, // space is set further below &_markBitMap, &_markStack, &mrias_cl); { - GCTraceTime(Trace, gc) t("Grey Object Rescan", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) t("Grey Object Rescan", _gc_timer_cm); // Iterate over the dirty cards, setting the corresponding bits in the // mod union table. { @@ -4939,7 +4937,7 @@ Universe::verify(); } { - GCTraceTime(Trace, gc) t("Root Rescan", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) t("Root Rescan", _gc_timer_cm); verify_work_stacks_empty(); @@ -4961,7 +4959,7 @@ } { - GCTraceTime(Trace, gc) t("Visit Unhandled CLDs", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) t("Visit Unhandled CLDs", _gc_timer_cm); verify_work_stacks_empty(); @@ -4980,7 +4978,7 @@ } { - GCTraceTime(Trace, gc) t("Dirty Klass Scan", _gc_timer_cm); + GCTraceTime(Trace, gc, phases) t("Dirty Klass Scan", _gc_timer_cm); verify_work_stacks_empty(); @@ -5184,7 +5182,7 @@ _span, &_markBitMap, &_markStack, &cmsKeepAliveClosure, false /* !preclean */); { - GCTraceTime(Debug, gc) t("Weak Refs Processing", _gc_timer_cm); + GCTraceTime(Debug, gc, phases) t("Reference Processing", _gc_timer_cm); ReferenceProcessorStats stats; if (rp->processing_is_mt()) { @@ -5226,7 +5224,7 @@ if (should_unload_classes()) { { - GCTraceTime(Debug, gc) t("Class Unloading", _gc_timer_cm); + GCTraceTime(Debug, gc, phases) t("Class Unloading", _gc_timer_cm); // Unload classes and purge the SystemDictionary. bool purged_class = SystemDictionary::do_unloading(&_is_alive_closure); @@ -5239,13 +5237,13 @@ } { - GCTraceTime(Debug, gc) t("Scrub Symbol Table", _gc_timer_cm); + GCTraceTime(Debug, gc, phases) t("Scrub Symbol Table", _gc_timer_cm); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } { - GCTraceTime(Debug, gc) t("Scrub String Table", _gc_timer_cm); + GCTraceTime(Debug, gc, phases) t("Scrub String Table", _gc_timer_cm); // Delete entries for dead interned strings. StringTable::unlink(&_is_alive_closure); } --- old/src/share/vm/gc/cms/parNewGeneration.cpp 2016-03-17 14:11:49.809530345 +0100 +++ new/src/share/vm/gc/cms/parNewGeneration.cpp 2016-03-17 14:11:49.657525224 +0100 @@ -901,7 +901,7 @@ size_policy->minor_collection_begin(); } - GCTraceTime(Trace, gc) t1("ParNew", NULL, gch->gc_cause()); + GCTraceTime(Trace, gc, phases) t1("ParNew", NULL, gch->gc_cause()); age_table()->clear(); to()->clear(SpaceDecorator::Mangle); --- old/src/share/vm/gc/cms/vmCMSOperations.cpp 2016-03-17 14:11:50.085539644 +0100 +++ new/src/share/vm/gc/cms/vmCMSOperations.cpp 2016-03-17 14:11:49.941534793 +0100 @@ -58,7 +58,7 @@ void VM_CMS_Operation::verify_before_gc() { if (VerifyBeforeGC && GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) { - GCTraceTime(Info, gc, verify) tm("Verify Before", _collector->_gc_timer_cm); + GCTraceTime(Info, gc, phases, verify) tm("Verify Before", _collector->_gc_timer_cm); HandleMark hm; FreelistLocker x(_collector); MutexLockerEx y(_collector->bitMapLock(), Mutex::_no_safepoint_check_flag); @@ -70,7 +70,7 @@ void VM_CMS_Operation::verify_after_gc() { if (VerifyAfterGC && GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) { - GCTraceTime(Info, gc, verify) tm("Verify After", _collector->_gc_timer_cm); + GCTraceTime(Info, gc, phases, verify) tm("Verify After", _collector->_gc_timer_cm); HandleMark hm; FreelistLocker x(_collector); MutexLockerEx y(_collector->bitMapLock(), Mutex::_no_safepoint_check_flag); --- old/src/share/vm/gc/g1/g1ConcurrentMark.cpp 2016-03-17 14:11:50.333548001 +0100 +++ new/src/share/vm/gc/g1/g1ConcurrentMark.cpp 2016-03-17 14:11:50.185543014 +0100 @@ -1123,7 +1123,7 @@ reset_marking_state(); } else { { - GCTraceTime(Debug, gc) trace("Aggregate Data", g1h->gc_timer_cm()); + GCTraceTime(Debug, gc, phases) trace("Aggregate Data", g1h->gc_timer_cm()); // Aggregate the per-task counting data that we have accumulated // while marking. @@ -2044,7 +2044,7 @@ // Inner scope to exclude the cleaning of the string and symbol // tables from the displayed time. { - GCTraceTime(Debug, gc) trace("Reference Processing", g1h->gc_timer_cm()); + GCTraceTime(Debug, gc, phases) trace("Reference Processing", g1h->gc_timer_cm()); ReferenceProcessor* rp = g1h->ref_processor_cm(); @@ -2133,28 +2133,24 @@ assert(_markStack.isEmpty(), "Marking should have completed"); // Unload Klasses, String, Symbols, Code Cache, etc. - { - GCTraceTime(Debug, gc) trace("Unloading", g1h->gc_timer_cm()); - - if (ClassUnloadingWithConcurrentMark) { - bool purged_classes; - - { - GCTraceTime(Trace, gc) trace("System Dictionary Unloading", g1h->gc_timer_cm()); - purged_classes = SystemDictionary::do_unloading(&g1_is_alive, false /* Defer klass cleaning */); - } + if (ClassUnloadingWithConcurrentMark) { + bool purged_classes; - { - GCTraceTime(Trace, gc) trace("Parallel Unloading", g1h->gc_timer_cm()); - weakRefsWorkParallelPart(&g1_is_alive, purged_classes); - } + { + GCTraceTime(Debug, gc, phases) trace("System Dictionary Unloading", g1h->gc_timer_cm()); + purged_classes = SystemDictionary::do_unloading(&g1_is_alive, false /* Defer klass cleaning */); } - if (G1StringDedup::is_enabled()) { - GCTraceTime(Trace, gc) trace("String Deduplication Unlink", g1h->gc_timer_cm()); - G1StringDedup::unlink(&g1_is_alive); + { + GCTraceTime(Debug, gc, phases) trace("Parallel Unloading", g1h->gc_timer_cm()); + weakRefsWorkParallelPart(&g1_is_alive, purged_classes); } } + + if (G1StringDedup::is_enabled()) { + GCTraceTime(Debug, gc, phases) trace("String Deduplication Unlink", g1h->gc_timer_cm()); + G1StringDedup::unlink(&g1_is_alive); + } } void G1ConcurrentMark::swapMarkBitMaps() { @@ -2272,7 +2268,7 @@ HandleMark hm; G1CollectedHeap* g1h = G1CollectedHeap::heap(); - GCTraceTime(Debug, gc) trace("Finalize Marking", g1h->gc_timer_cm()); + GCTraceTime(Debug, gc, phases) trace("Finalize Marking", g1h->gc_timer_cm()); g1h->ensure_parsability(false); --- old/src/share/vm/gc/g1/g1MarkSweep.cpp 2016-03-17 14:11:50.653558783 +0100 +++ new/src/share/vm/gc/g1/g1MarkSweep.cpp 2016-03-17 14:11:50.505553796 +0100 @@ -122,7 +122,7 @@ void G1MarkSweep::mark_sweep_phase1(bool& marked_for_unloading, bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - GCTraceTime(Trace, gc) tm("Phase 1: Mark live objects", gc_timer()); + GCTraceTime(Info, gc, phases) tm("Phase 1: Mark live objects", gc_timer()); G1CollectedHeap* g1h = G1CollectedHeap::heap(); @@ -137,25 +137,28 @@ &follow_code_closure); } - // Process reference objects found during marking - ReferenceProcessor* rp = GenMarkSweep::ref_processor(); - assert(rp == g1h->ref_processor_stw(), "Sanity"); - - rp->setup_policy(clear_all_softrefs); - const ReferenceProcessorStats& stats = - rp->process_discovered_references(&GenMarkSweep::is_alive, - &GenMarkSweep::keep_alive, - &GenMarkSweep::follow_stack_closure, - NULL, - gc_timer()); - gc_tracer()->report_gc_reference_stats(stats); + { + GCTraceTime(Debug, gc, phases) trace("Reference Processing", gc_timer()); + // Process reference objects found during marking + ReferenceProcessor* rp = GenMarkSweep::ref_processor(); + assert(rp == g1h->ref_processor_stw(), "Sanity"); + + rp->setup_policy(clear_all_softrefs); + const ReferenceProcessorStats& stats = + rp->process_discovered_references(&GenMarkSweep::is_alive, + &GenMarkSweep::keep_alive, + &GenMarkSweep::follow_stack_closure, + NULL, + gc_timer()); + gc_tracer()->report_gc_reference_stats(stats); + } // This is the point where the entire marking should have completed. assert(GenMarkSweep::_marking_stack.is_empty(), "Marking should have completed"); { - GCTraceTime(Debug, gc) trace("Class Unloading", gc_timer()); + GCTraceTime(Debug, gc, phases) trace("Class Unloading", gc_timer()); // Unload classes and purge the SystemDictionary. bool purged_class = SystemDictionary::do_unloading(&GenMarkSweep::is_alive); @@ -168,13 +171,13 @@ } { - GCTraceTime(Debug, gc) trace("Scrub String and Symbol Tables", gc_timer()); + GCTraceTime(Debug, gc, phases) trace("Scrub String and Symbol Tables", gc_timer()); // Delete entries for dead interned string and clean up unreferenced symbols in symbol table. g1h->unlink_string_and_symbol_table(&GenMarkSweep::is_alive); } if (G1StringDedup::is_enabled()) { - GCTraceTime(Debug, gc) trace("String Deduplication Unlink", gc_timer()); + GCTraceTime(Debug, gc, phases) trace("String Deduplication Unlink", gc_timer()); G1StringDedup::unlink(&GenMarkSweep::is_alive); } @@ -209,7 +212,7 @@ // phase2, phase3 and phase4, but the ValidateMarkSweep live oops // tracking expects us to do so. See comment under phase4. - GCTraceTime(Trace, gc) tm("Phase 2: Compute new object addresses", gc_timer()); + GCTraceTime(Info, gc, phases) tm("Phase 2: Compute new object addresses", gc_timer()); prepare_compaction(); } @@ -236,7 +239,7 @@ G1CollectedHeap* g1h = G1CollectedHeap::heap(); // Adjust the pointers to reflect the new locations - GCTraceTime(Trace, gc) tm("Phase 3: Adjust pointers", gc_timer()); + GCTraceTime(Info, gc, phases) tm("Phase 3: Adjust pointers", gc_timer()); // Need cleared claim bits for the roots processing ClassLoaderDataGraph::clear_claimed_marks(); @@ -297,7 +300,7 @@ // to use a higher index (saved from phase2) when verifying perm_gen. G1CollectedHeap* g1h = G1CollectedHeap::heap(); - GCTraceTime(Trace, gc) tm("Phase 4: Move objects", gc_timer()); + GCTraceTime(Info, gc, phases) tm("Phase 4: Move objects", gc_timer()); G1SpaceCompactClosure blk; g1h->heap_region_iterate(&blk); --- old/src/share/vm/gc/parallel/psMarkSweep.cpp 2016-03-17 14:11:50.909567408 +0100 +++ new/src/share/vm/gc/parallel/psMarkSweep.cpp 2016-03-17 14:11:50.757562287 +0100 @@ -493,7 +493,7 @@ void PSMarkSweep::mark_sweep_phase1(bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - GCTraceTime(Trace, gc) tm("Phase 1: Mark live objects", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 1: Mark live objects", _gc_timer); ParallelScavengeHeap* heap = ParallelScavengeHeap::heap(); @@ -523,6 +523,8 @@ // Process reference objects found during marking { + GCTraceTime(Debug, gc, phases) t("Reference Processing", _gc_timer); + ref_processor()->setup_policy(clear_all_softrefs); const ReferenceProcessorStats& stats = ref_processor()->process_discovered_references( @@ -534,7 +536,7 @@ assert(_marking_stack.is_empty(), "Marking should have completed"); { - GCTraceTime(Debug, gc) t("Class Unloading", _gc_timer); + GCTraceTime(Debug, gc, phases) t("Class Unloading", _gc_timer); // Unload classes and purge the SystemDictionary. bool purged_class = SystemDictionary::do_unloading(is_alive_closure()); @@ -547,13 +549,13 @@ } { - GCTraceTime(Debug, gc) t("Scrub String Table", _gc_timer); + GCTraceTime(Debug, gc, phases) t("Scrub String Table", _gc_timer); // Delete entries for dead interned strings. StringTable::unlink(is_alive_closure()); } { - GCTraceTime(Debug, gc) t("Scrub Symbol Table", _gc_timer); + GCTraceTime(Debug, gc, phases) t("Scrub Symbol Table", _gc_timer); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } @@ -563,7 +565,7 @@ void PSMarkSweep::mark_sweep_phase2() { - GCTraceTime(Trace, gc) tm("Phase 2: Compute new object addresses", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 2: Compute new object addresses", _gc_timer); // Now all live objects are marked, compute the new object addresses. @@ -583,7 +585,7 @@ void PSMarkSweep::mark_sweep_phase3() { // Adjust the pointers to reflect the new locations - GCTraceTime(Trace, gc) tm("Phase 3: Adjust pointers", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 3: Adjust pointers", _gc_timer); ParallelScavengeHeap* heap = ParallelScavengeHeap::heap(); PSYoungGen* young_gen = heap->young_gen(); @@ -623,7 +625,7 @@ void PSMarkSweep::mark_sweep_phase4() { EventMark m("4 compact heap"); - GCTraceTime(Trace, gc) tm("Phase 4: Move objects", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 4: Move objects", _gc_timer); // All pointers are now adjusted, move objects accordingly --- old/src/share/vm/gc/parallel/psParallelCompact.cpp 2016-03-17 14:11:51.189576842 +0100 +++ new/src/share/vm/gc/parallel/psParallelCompact.cpp 2016-03-17 14:11:51.029571451 +0100 @@ -195,10 +195,10 @@ }; void PSParallelCompact::print_region_ranges() { - if (!log_develop_is_enabled(Trace, gc, compaction, phases)) { + if (!log_develop_is_enabled(Trace, gc, compaction)) { return; } - LogHandle(gc, compaction, phases) log; + LogHandle(gc, compaction) log; ResourceMark rm; Universe::print_on(log.trace_stream()); log.trace("space bottom top end new_top"); @@ -225,7 +225,7 @@ ParallelCompactData& sd = PSParallelCompact::summary_data(); size_t dci = c->destination() ? sd.addr_to_region_idx(c->destination()) : 0; - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( REGION_IDX_FORMAT " " PTR_FORMAT " " REGION_IDX_FORMAT " " PTR_FORMAT " " REGION_DATA_FORMAT " " REGION_DATA_FORMAT " " @@ -258,14 +258,14 @@ ++i; } - log_develop_trace(gc, compaction, phases)("summary_data_bytes=" SIZE_FORMAT, total_words * HeapWordSize); + log_develop_trace(gc, compaction)("summary_data_bytes=" SIZE_FORMAT, total_words * HeapWordSize); } void print_generic_summary_data(ParallelCompactData& summary_data, SpaceInfo* space_info) { - if (!log_develop_is_enabled(Trace, gc, compaction, phases)) { + if (!log_develop_is_enabled(Trace, gc, compaction)) { return; } @@ -296,7 +296,7 @@ size_t i = summary_data.addr_to_region_idx(space->bottom()); while (i < end_region && summary_data.region(i)->data_size() == region_size) { ParallelCompactData::RegionData* c = summary_data.region(i); - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( SIZE_FORMAT_W(5) " " PTR_FORMAT " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " %d", i, p2i(c->destination()), c->partial_obj_size(), c->live_obj_size(), @@ -330,7 +330,7 @@ } ParallelCompactData::RegionData* c = summary_data.region(i); - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( SIZE_FORMAT_W(5) " " PTR_FORMAT " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " %d" "%12.10f " SIZE_FORMAT_W(10) " " SIZE_FORMAT_W(10), i, p2i(c->destination()), @@ -346,21 +346,21 @@ // Any remaining regions are empty. Print one more if there is one. if (i < end_region) { ParallelCompactData::RegionData* c = summary_data.region(i); - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( SIZE_FORMAT_W(5) " " PTR_FORMAT " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " %d", i, p2i(c->destination()), c->partial_obj_size(), c->live_obj_size(), c->data_size(), c->source_region(), c->destination_count()); } - log_develop_trace(gc, compaction, phases)("max: " SIZE_FORMAT_W(4) " d2r=" SIZE_FORMAT_W(10) " l2r=" SIZE_FORMAT_W(10) " max_ratio=%14.12f", - max_reclaimed_ratio_region, max_dead_to_right, max_live_to_right, max_reclaimed_ratio); + log_develop_trace(gc, compaction)("max: " SIZE_FORMAT_W(4) " d2r=" SIZE_FORMAT_W(10) " l2r=" SIZE_FORMAT_W(10) " max_ratio=%14.12f", + max_reclaimed_ratio_region, max_dead_to_right, max_live_to_right, max_reclaimed_ratio); } void print_initial_summary_data(ParallelCompactData& summary_data, SpaceInfo* space_info) { - if (!log_develop_is_enabled(Trace, gc, compaction, phases)) { + if (!log_develop_is_enabled(Trace, gc, compaction)) { return; } @@ -621,7 +621,7 @@ sr->partial_obj_size())); const size_t end_idx = addr_to_region_idx(target_end); - log_develop_trace(gc, compaction, phases)("split: clearing source_region field in [" SIZE_FORMAT ", " SIZE_FORMAT ")", beg_idx, end_idx); + log_develop_trace(gc, compaction)("split: clearing source_region field in [" SIZE_FORMAT ", " SIZE_FORMAT ")", beg_idx, end_idx); for (size_t idx = beg_idx; idx < end_idx; ++idx) { _region_data[idx].set_source_region(0); } @@ -641,22 +641,22 @@ *target_next = split_destination + partial_obj_size; HeapWord* const source_next = region_to_addr(split_region) + partial_obj_size; - if (log_develop_is_enabled(Trace, gc, compaction, phases)) { + if (log_develop_is_enabled(Trace, gc, compaction)) { const char * split_type = partial_obj_size == 0 ? "easy" : "hard"; - log_develop_trace(gc, compaction, phases)("%s split: src=" PTR_FORMAT " src_c=" SIZE_FORMAT " pos=" SIZE_FORMAT, - split_type, p2i(source_next), split_region, partial_obj_size); - log_develop_trace(gc, compaction, phases)("%s split: dst=" PTR_FORMAT " dst_c=" SIZE_FORMAT " tn=" PTR_FORMAT, - split_type, p2i(split_destination), - addr_to_region_idx(split_destination), - p2i(*target_next)); + log_develop_trace(gc, compaction)("%s split: src=" PTR_FORMAT " src_c=" SIZE_FORMAT " pos=" SIZE_FORMAT, + split_type, p2i(source_next), split_region, partial_obj_size); + log_develop_trace(gc, compaction)("%s split: dst=" PTR_FORMAT " dst_c=" SIZE_FORMAT " tn=" PTR_FORMAT, + split_type, p2i(split_destination), + addr_to_region_idx(split_destination), + p2i(*target_next)); if (partial_obj_size != 0) { HeapWord* const po_beg = split_info.destination(); HeapWord* const po_end = po_beg + split_info.partial_obj_size(); - log_develop_trace(gc, compaction, phases)("%s split: po_beg=" PTR_FORMAT " " SIZE_FORMAT " po_end=" PTR_FORMAT " " SIZE_FORMAT, - split_type, - p2i(po_beg), addr_to_region_idx(po_beg), - p2i(po_end), addr_to_region_idx(po_end)); + log_develop_trace(gc, compaction)("%s split: po_beg=" PTR_FORMAT " " SIZE_FORMAT " po_end=" PTR_FORMAT " " SIZE_FORMAT, + split_type, + p2i(po_beg), addr_to_region_idx(po_beg), + p2i(po_end), addr_to_region_idx(po_end)); } } @@ -670,7 +670,7 @@ HeapWord** target_next) { HeapWord* const source_next_val = source_next == NULL ? NULL : *source_next; - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( "sb=" PTR_FORMAT " se=" PTR_FORMAT " sn=" PTR_FORMAT "tb=" PTR_FORMAT " te=" PTR_FORMAT " tn=" PTR_FORMAT, p2i(source_beg), p2i(source_end), p2i(source_next_val), @@ -938,7 +938,7 @@ // at each young gen gc. Do the update unconditionally (even though a // promotion failure does not swap spaces) because an unknown number of young // collections will have swapped the spaces an unknown number of times. - GCTraceTime(Trace, gc, phases) tm("Pre Compact", &_gc_timer); + GCTraceTime(Debug, gc, phases) tm("Pre Compact", &_gc_timer); ParallelScavengeHeap* heap = ParallelScavengeHeap::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()); @@ -981,7 +981,7 @@ void PSParallelCompact::post_compact() { - GCTraceTime(Trace, gc, phases) tm("Post Compact", &_gc_timer); + GCTraceTime(Info, gc, phases) tm("Post Compact", &_gc_timer); for (unsigned int id = old_space_id; id < last_space_id; ++id) { // Clear the marking bitmap, summary data and split info. @@ -1524,7 +1524,7 @@ } } - if (log_develop_is_enabled(Trace, gc, compaction, phases)) { + if (log_develop_is_enabled(Trace, gc, compaction)) { const size_t region_size = ParallelCompactData::RegionSize; HeapWord* const dense_prefix_end = _space_info[id].dense_prefix(); const size_t dp_region = _summary_data.addr_to_region_idx(dense_prefix_end); @@ -1532,7 +1532,7 @@ HeapWord* const new_top = _space_info[id].new_top(); const HeapWord* nt_aligned_up = _summary_data.region_align_up(new_top); const size_t cr_words = pointer_delta(nt_aligned_up, dense_prefix_end); - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( "id=%d cap=" SIZE_FORMAT " dp=" PTR_FORMAT " " "dp_region=" SIZE_FORMAT " " "dp_count=" SIZE_FORMAT " " "cr_count=" SIZE_FORMAT " " "nt=" PTR_FORMAT, @@ -1548,7 +1548,7 @@ SpaceId src_space_id, HeapWord* src_beg, HeapWord* src_end) { - log_develop_trace(gc, compaction, phases)( + log_develop_trace(gc, compaction)( "Summarizing %d [%s] into %d [%s]: " "src=" PTR_FORMAT "-" PTR_FORMAT " " SIZE_FORMAT "-" SIZE_FORMAT " " @@ -1568,7 +1568,7 @@ void PSParallelCompact::summary_phase(ParCompactionManager* cm, bool maximum_compaction) { - GCTraceTime(Trace, gc, phases) tm("Summary Phase", &_gc_timer); + GCTraceTime(Info, gc, phases) tm("Summary Phase", &_gc_timer); #ifdef ASSERT if (TraceParallelOldGCMarkingPhase) { @@ -1584,7 +1584,7 @@ // Quick summarization of each space into itself, to see how much is live. summarize_spaces_quick(); - log_develop_trace(gc, compaction, phases)("summary phase: after summarizing each space to self"); + log_develop_trace(gc, compaction)("summary phase: after summarizing each space to self"); NOT_PRODUCT(print_region_ranges()); NOT_PRODUCT(print_initial_summary_data(_summary_data, _space_info)); @@ -1660,7 +1660,7 @@ } } - log_develop_trace(gc, compaction, phases)("Summary_phase: after final summarization"); + log_develop_trace(gc, compaction)("Summary_phase: after final summarization"); NOT_PRODUCT(print_region_ranges()); NOT_PRODUCT(print_initial_summary_data(_summary_data, _space_info)); } @@ -2042,7 +2042,7 @@ bool maximum_heap_compaction, ParallelOldTracer *gc_tracer) { // Recursively traverse all live objects and mark them - GCTraceTime(Trace, gc, phases) tm("Marking Phase", &_gc_timer); + GCTraceTime(Info, gc, phases) tm("Marking Phase", &_gc_timer); ParallelScavengeHeap* heap = ParallelScavengeHeap::heap(); uint parallel_gc_threads = heap->gc_task_manager()->workers(); @@ -2057,7 +2057,7 @@ ClassLoaderDataGraph::clear_claimed_marks(); { - GCTraceTime(Trace, gc, phases) tm("Par Mark", &_gc_timer); + GCTraceTime(Debug, gc, phases) tm("Par Mark", &_gc_timer); ParallelScavengeHeap::ParStrongRootsScope psrs; @@ -2086,7 +2086,7 @@ // Process reference objects found during marking { - GCTraceTime(Trace, gc, phases) tm("Reference Processing", &_gc_timer); + GCTraceTime(Debug, gc, phases) tm("Reference Processing", &_gc_timer); ReferenceProcessorStats stats; if (ref_processor()->processing_is_mt()) { @@ -2107,7 +2107,7 @@ assert(cm->marking_stacks_empty(), "Marking should have completed"); { - GCTraceTime(Debug, gc) tm_m("Class Unloading", &_gc_timer); + GCTraceTime(Debug, gc, phases) tm_m("Class Unloading", &_gc_timer); // Follow system dictionary roots and unload classes. bool purged_class = SystemDictionary::do_unloading(is_alive_closure()); @@ -2120,13 +2120,13 @@ } { - GCTraceTime(Debug, gc) t("Scrub String Table", &_gc_timer); + GCTraceTime(Debug, gc, phases) t("Scrub String Table", &_gc_timer); // Delete entries for dead interned strings. StringTable::unlink(is_alive_closure()); } { - GCTraceTime(Debug, gc) t("Scrub Symbol Table", &_gc_timer); + GCTraceTime(Debug, gc, phases) t("Scrub Symbol Table", &_gc_timer); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } @@ -2136,7 +2136,7 @@ void PSParallelCompact::adjust_roots(ParCompactionManager* cm) { // Adjust the pointers to reflect the new locations - GCTraceTime(Trace, gc, phases) tm("Adjust Roots", &_gc_timer); + GCTraceTime(Info, gc, phases) tm("Adjust Roots", &_gc_timer); // Need new claim bits when tracing through and adjusting pointers. ClassLoaderDataGraph::clear_claimed_marks(); @@ -2410,7 +2410,7 @@ #endif // #ifdef ASSERT void PSParallelCompact::compact() { - GCTraceTime(Trace, gc, phases) tm("Compaction Phase", &_gc_timer); + GCTraceTime(Info, gc, phases) tm("Compaction Phase", &_gc_timer); ParallelScavengeHeap* heap = ParallelScavengeHeap::heap(); PSOldGen* old_gen = heap->old_gen(); --- old/src/share/vm/gc/parallel/psScavenge.cpp 2016-03-17 14:11:51.501587355 +0100 +++ new/src/share/vm/gc/parallel/psScavenge.cpp 2016-03-17 14:11:51.385583446 +0100 @@ -404,7 +404,7 @@ // Process reference objects discovered during scavenge { - GCTraceTime(Debug, gc, phases) tm("References", &_gc_timer); + GCTraceTime(Debug, gc, phases) tm("Reference Processing", &_gc_timer); reference_processor()->setup_policy(false); // not always_clear reference_processor()->set_active_mt_degree(active_workers); @@ -433,7 +433,7 @@ } { - GCTraceTime(Debug, gc, phases) tm("StringTable", &_gc_timer); + GCTraceTime(Debug, gc, phases) tm("Scrub String Table", &_gc_timer); // 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); --- old/src/share/vm/gc/serial/defNewGeneration.cpp 2016-03-17 14:11:51.765596250 +0100 +++ new/src/share/vm/gc/serial/defNewGeneration.cpp 2016-03-17 14:11:51.609590994 +0100 @@ -594,7 +594,7 @@ init_assuming_no_promotion_failure(); - GCTraceTime(Trace, gc) tm("DefNew", NULL, gch->gc_cause()); + GCTraceTime(Trace, gc, phases) tm("DefNew", NULL, gch->gc_cause()); gch->trace_heap_before_gc(&gc_tracer); --- old/src/share/vm/gc/serial/genMarkSweep.cpp 2016-03-17 14:11:52.013604606 +0100 +++ new/src/share/vm/gc/serial/genMarkSweep.cpp 2016-03-17 14:11:51.877600024 +0100 @@ -180,7 +180,7 @@ void GenMarkSweep::mark_sweep_phase1(bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - GCTraceTime(Trace, gc) tm("Phase 1: Mark live objects", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 1: Mark live objects", _gc_timer); GenCollectedHeap* gch = GenCollectedHeap::heap(); @@ -208,6 +208,8 @@ // Process reference objects found during marking { + GCTraceTime(Debug, gc, phases) tm_m("Reference Processing", gc_timer()); + ref_processor()->setup_policy(clear_all_softrefs); const ReferenceProcessorStats& stats = ref_processor()->process_discovered_references( @@ -219,7 +221,7 @@ assert(_marking_stack.is_empty(), "Marking should have completed"); { - GCTraceTime(Debug, gc) tm_m("Class Unloading", gc_timer()); + GCTraceTime(Debug, gc, phases) tm_m("Class Unloading", gc_timer()); // Unload classes and purge the SystemDictionary. bool purged_class = SystemDictionary::do_unloading(&is_alive); @@ -232,13 +234,13 @@ } { - GCTraceTime(Debug, gc) t("Scrub String Table", gc_timer()); + GCTraceTime(Debug, gc, phases) t("Scrub String Table", gc_timer()); // Delete entries for dead interned strings. StringTable::unlink(&is_alive); } { - GCTraceTime(Debug, gc) t("Scrub Symbol Table", gc_timer()); + GCTraceTime(Debug, gc, phases) t("Scrub Symbol Table", gc_timer()); // Clean up unreferenced symbols in symbol table. SymbolTable::unlink(); } @@ -263,7 +265,7 @@ GenCollectedHeap* gch = GenCollectedHeap::heap(); - GCTraceTime(Trace, gc) tm("Phase 2: Compute new object addresses", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 2: Compute new object addresses", _gc_timer); gch->prepare_for_compaction(); } @@ -279,7 +281,7 @@ GenCollectedHeap* gch = GenCollectedHeap::heap(); // Adjust the pointers to reflect the new locations - GCTraceTime(Trace, gc) tm("Phase 3: Adjust pointers", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 3: Adjust pointers", gc_timer()); // Need new claim bits for the pointer adjustment tracing. ClassLoaderDataGraph::clear_claimed_marks(); @@ -331,7 +333,7 @@ // to use a higher index (saved from phase2) when verifying perm_gen. GenCollectedHeap* gch = GenCollectedHeap::heap(); - GCTraceTime(Trace, gc) tm("Phase 4: Move objects", _gc_timer); + GCTraceTime(Info, gc, phases) tm("Phase 4: Move objects", _gc_timer); GenCompactClosure blk; gch->generation_iterate(&blk, true); --- old/src/share/vm/gc/shared/genCollectedHeap.cpp 2016-03-17 14:11:52.257612827 +0100 +++ new/src/share/vm/gc/shared/genCollectedHeap.cpp 2016-03-17 14:11:52.121608245 +0100 @@ -315,7 +315,7 @@ bool is_tlab, bool run_verification, bool clear_soft_refs, bool restore_marks_for_biased_locking) { FormatBuffer<> title("Collect gen: %s", gen->short_name()); - GCTraceTime(Debug, gc) t1(title); + GCTraceTime(Trace, gc, phases) t1(title); TraceCollectorStats tcs(gen->counters()); TraceMemoryManagerStats tmms(gen->kind(),gc_cause()); --- old/src/share/vm/logging/logPrefix.hpp 2016-03-17 14:11:52.533622127 +0100 +++ new/src/share/vm/logging/logPrefix.hpp 2016-03-17 14:11:52.381617005 +0100 @@ -45,7 +45,6 @@ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, barrier)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, classhisto)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, compaction)) \ - LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, compaction, phases)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, cpu)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, ergo, cset)) \