--- old/src/share/vm/gc/shared/referenceProcessorPhaseTimes.cpp 2017-08-03 16:11:13.501642912 -0700 +++ new/src/share/vm/gc/shared/referenceProcessorPhaseTimes.cpp 2017-08-03 16:11:13.361642917 -0700 @@ -27,6 +27,7 @@ #include "gc/shared/referenceProcessorPhaseTimes.hpp" #include "gc/shared/referenceProcessor.inline.hpp" #include "logging/log.hpp" +#include "logging/logStream.hpp" RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers number, ReferenceProcessorPhaseTimes* phase_times, @@ -203,10 +204,8 @@ phase_times()->set_par_phase_time_ms(ReferenceProcessorPhaseTimes::RefEnqueue, elapsed); } -ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(GCTimer* gc_timer, - uint max_gc_threads, - bool processing_is_mt) : - _gc_timer(gc_timer), _processing_is_mt(processing_is_mt) { +ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(GCTimer* gc_timer, uint max_gc_threads) : + _gc_timer(gc_timer), _processing_is_mt(false) { for (int i = 0; i < RefParPhaseMax; i++) { _worker_time_sec[i] = new WorkerDataArray(max_gc_threads, "Process lists (ms)"); @@ -312,7 +311,7 @@ _ref_enqueued[ref_type_2_index(ref_type)] = count; } -double ReferenceProcessorPhaseTimes::balance_queues_time_ms(ReferenceType ref_type) const{ +double ReferenceProcessorPhaseTimes::balance_queues_time_ms(ReferenceType ref_type) const { ASSERT_REF_TYPE(ref_type); return _balance_queues_time_ms[ref_type_2_index(ref_type)]; } @@ -323,40 +322,40 @@ } ReferenceProcessorPhaseTimes::RefProcParPhases -ReferenceProcessorPhaseTimes::par_phase(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number) const { +ReferenceProcessorPhaseTimes::par_phase(RefProcPhaseNumbers phase_number) const { ASSERT_PHASE_NUMBER(phase_number); ASSERT_REF_TYPE(_processing_ref_type); - int result = ReferenceProcessorPhaseTimes::SoftRefPhase1; + int result = SoftRefPhase1; switch(_processing_ref_type) { case REF_SOFT: - result = (int)ReferenceProcessorPhaseTimes::SoftRefPhase1; + result = (int)SoftRefPhase1; result += phase_number; - assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::SoftRefPhase1 && - (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::SoftRefPhase3, + assert((RefProcParPhases)result >= SoftRefPhase1 && + (RefProcParPhases)result <= SoftRefPhase3, "Invariant (%d)", result); break; case REF_WEAK: - result = (int)ReferenceProcessorPhaseTimes::WeakRefPhase2; + result = (int)WeakRefPhase2; result += (phase_number - 1); - assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::WeakRefPhase2 && - (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::WeakRefPhase3, + assert((RefProcParPhases)result >= WeakRefPhase2 && + (RefProcParPhases)result <= WeakRefPhase3, "Invariant (%d)", result); break; case REF_FINAL: - result = (int)ReferenceProcessorPhaseTimes::FinalRefPhase2; + result = (int)FinalRefPhase2; result += (phase_number - 1); - assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::FinalRefPhase2 && - (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::FinalRefPhase3, + assert((RefProcParPhases)result >= FinalRefPhase2 && + (RefProcParPhases)result <= FinalRefPhase3, "Invariant (%d)", result); break; case REF_PHANTOM: - result = (int)ReferenceProcessorPhaseTimes::PhantomRefPhase2; + result = (int)PhantomRefPhase2; result += (phase_number - 1); - assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::PhantomRefPhase2 && - (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::PhantomRefPhase3, + assert((RefProcParPhases)result >= PhantomRefPhase2 && + (RefProcParPhases)result <= PhantomRefPhase3, "Invariant (%d)", result); break; default: @@ -368,9 +367,9 @@ return (RefProcParPhases)result; } -void ReferenceProcessorPhaseTimes::print_enqueue_phase(uint base_indent, bool print_total) { +void ReferenceProcessorPhaseTimes::print_enqueue_phase(uint base_indent, bool print_total) const { if (print_total) { - print_phase(ReferenceProcessorPhaseTimes::RefEnqueue, base_indent); + print_phase(RefEnqueue, base_indent); } log_debug(gc, phases, ref)("%sReference Counts: Soft: " SIZE_FORMAT " Weak: " SIZE_FORMAT @@ -381,13 +380,14 @@ #define TIME_FORMAT "%.1lfms" -void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) { +void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) const { if (print_total) { - Log(gc, phases, ref) log; + LogTarget(Debug, gc, phases, ref) lt; - if (log.is_level(LogLevel::Debug)) { - log.debug_stream()->print_cr("%s%s: " TIME_FORMAT, - Indents[base_indent], "Reference Processing", total_time_ms()); + if (lt.is_enabled()) { + LogStream ls(lt); + ls.print_cr("%s%s: " TIME_FORMAT, + Indents[base_indent], "Reference Processing", total_time_ms()); } } @@ -398,69 +398,73 @@ print_reference(REF_PHANTOM, next_indent); } -void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) { - Log(gc, phases, ref) log; +void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) const { + LogTarget(Debug, gc, phases, ref) lt; - if (log.is_level(LogLevel::Debug)) { + if (lt.is_enabled()) { + LogStream ls(lt); uint next_indent = base_indent + 1; - outputStream* out = log.debug_stream(); ResourceMark rm; - out->print_cr("%s%s: " TIME_FORMAT, - Indents[base_indent], ref_type_2_string(ref_type), ref_proc_time_ms(ref_type)); + ls.print_cr("%s%s: " TIME_FORMAT, + Indents[base_indent], ref_type_2_string(ref_type), ref_proc_time_ms(ref_type)); double balance_time = balance_queues_time_ms(ref_type); if (balance_time != uninitialized()) { - out->print_cr("%s%s " TIME_FORMAT, Indents[next_indent], "Balance queues:", balance_time); + ls.print_cr("%s%s " TIME_FORMAT, Indents[next_indent], "Balance queues:", balance_time); } switch(ref_type) { case REF_SOFT: print_phase(SoftRefPhase1, next_indent); - print_phase(ReferenceProcessorPhaseTimes::SoftRefPhase2, next_indent); - print_phase(ReferenceProcessorPhaseTimes::SoftRefPhase3, next_indent); + print_phase(SoftRefPhase2, next_indent); + print_phase(SoftRefPhase3, next_indent); break; case REF_WEAK: - print_phase(ReferenceProcessorPhaseTimes::WeakRefPhase2, next_indent); - print_phase(ReferenceProcessorPhaseTimes::WeakRefPhase3, next_indent); + print_phase(WeakRefPhase2, next_indent); + print_phase(WeakRefPhase3, next_indent); break; case REF_FINAL: - print_phase(ReferenceProcessorPhaseTimes::FinalRefPhase2, next_indent); - print_phase(ReferenceProcessorPhaseTimes::FinalRefPhase3, next_indent); + print_phase(FinalRefPhase2, next_indent); + print_phase(FinalRefPhase3, next_indent); break; case REF_PHANTOM: - print_phase(ReferenceProcessorPhaseTimes::PhantomRefPhase2, next_indent); - print_phase(ReferenceProcessorPhaseTimes::PhantomRefPhase3, next_indent); + print_phase(PhantomRefPhase2, next_indent); + print_phase(PhantomRefPhase3, next_indent); break; default: ShouldNotReachHere(); } - out->print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Discovered:", ref_discovered(ref_type)); - out->print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Cleared:", ref_cleared(ref_type)); + ls.print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Discovered:", ref_discovered(ref_type)); + ls.print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Cleared:", ref_cleared(ref_type)); } } -void ReferenceProcessorPhaseTimes::print_phase(RefProcParPhases phase, uint indent) { +void ReferenceProcessorPhaseTimes::print_phase(RefProcParPhases phase, uint indent) const { double phase_time = par_phase_time_ms(phase); if (phase_time != uninitialized()) { - Log(gc, phases, ref) log; + LogTarget(Debug, gc, phases, ref) lt; - log.debug_stream()->print_cr("%s%s%s " TIME_FORMAT, - Indents[indent], - phase_enum_2_phase_string(phase), - indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */ - phase_time); - if (processing_is_mt() && log.is_level(LogLevel::Trace)) { - outputStream* out = log.trace_stream(); + LogStream ls(lt); - out->print("%s", Indents[indent + 1]); + ls.print_cr("%s%s%s " TIME_FORMAT, + Indents[indent], + phase_enum_2_phase_string(phase), + indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */ + phase_time); + + LogTarget(Trace, gc, phases, ref) lt2; + if (_processing_is_mt && lt2.is_enabled()) { + LogStream ls(lt2); + + ls.print("%s", Indents[indent + 1]); // worker_time_sec is recorded in seconds but it will be printed in milliseconds. - worker_time_sec(phase)->print_summary_on(out, true); + worker_time_sec(phase)->print_summary_on(&ls, true); } } }