--- /dev/null 2017-08-01 10:28:06.054051740 -0700 +++ new/src/share/vm/gc/shared/referenceProcessorPhaseTimes.cpp 2017-08-03 16:11:46.369641767 -0700 @@ -0,0 +1,475 @@ +/* + * Copyright (c) 2017, 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/shared/gcTimer.hpp" +#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, + uint worker_id) : + _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) { + assert (phase_times != NULL, "Invariant"); + + _worker_time = phase_times->worker_time_sec(phase_times->par_phase(number)); +} + +RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcParPhases phase, + ReferenceProcessorPhaseTimes* phase_times, + uint worker_id) : + _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) { + assert (phase_times != NULL, "Invariant"); + + _worker_time = phase_times->worker_time_sec(phase); +} + +RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() { + _worker_time->set(_worker_id, os::elapsedTime() - _start_time); +} + +RefProcPhaseTimeBaseTracker::RefProcPhaseTimeBaseTracker(const char* title, + ReferenceProcessorPhaseTimes* phase_times) : + _title(title), _phase_times(phase_times), _start_ticks(), _end_ticks() { + assert(_phase_times != NULL, "Invariant"); + + _start_ticks.stamp(); + if (_phase_times->gc_timer() != NULL) { + _phase_times->gc_timer()->register_gc_phase_start(_title, _start_ticks); + } +} + +static const char* phase_enum_2_phase_string(ReferenceProcessorPhaseTimes::RefProcParPhases phase) { + switch(phase) { + case ReferenceProcessorPhaseTimes::SoftRefPhase1: + return "Phase1"; + case ReferenceProcessorPhaseTimes::SoftRefPhase2: + case ReferenceProcessorPhaseTimes::WeakRefPhase2: + case ReferenceProcessorPhaseTimes::FinalRefPhase2: + case ReferenceProcessorPhaseTimes::PhantomRefPhase2: + return "Phase2"; + case ReferenceProcessorPhaseTimes::SoftRefPhase3: + case ReferenceProcessorPhaseTimes::WeakRefPhase3: + case ReferenceProcessorPhaseTimes::FinalRefPhase3: + case ReferenceProcessorPhaseTimes::PhantomRefPhase3: + return "Phase3"; + case ReferenceProcessorPhaseTimes::RefEnqueue: + return "Reference Enqueuing"; + default: + ShouldNotReachHere(); + return NULL; + } +} + +static const char* Indents[6] = {"", " ", " ", " ", " ", " "}; + +Ticks RefProcPhaseTimeBaseTracker::end_ticks() { + // If ASSERT is defined, the default value of Ticks will be -2. + if (_end_ticks.value() <= 0) { + _end_ticks.stamp(); + } + + return _end_ticks; +} + +double RefProcPhaseTimeBaseTracker::elapsed_time() { + jlong end_value = end_ticks().value(); + + return TimeHelper::counter_to_millis(end_value - _start_ticks.value()); +} + +RefProcPhaseTimeBaseTracker::~RefProcPhaseTimeBaseTracker() { + if (_phase_times->gc_timer() != NULL) { + Ticks ticks = end_ticks(); + _phase_times->gc_timer()->register_gc_phase_end(ticks); + } +} + +RefProcBalanceQueuesTimeTracker::RefProcBalanceQueuesTimeTracker(ReferenceProcessorPhaseTimes* phase_times) : + RefProcPhaseTimeBaseTracker("Balance queues", phase_times) {} + +RefProcBalanceQueuesTimeTracker::~RefProcBalanceQueuesTimeTracker() { + double elapsed = elapsed_time(); + phase_times()->set_balance_queues_time_ms(phase_times()->processing_ref_type(), elapsed); +} + +#define ASSERT_REF_TYPE(ref_type) assert(ref_type >= REF_SOFT && ref_type <= REF_PHANTOM, \ + "Invariant (%d)", (int)ref_type) + +#define ASSERT_PHASE_NUMBER(phase_number) assert(phase_number >= ReferenceProcessorPhaseTimes::RefPhase1 && \ + phase_number <= ReferenceProcessorPhaseTimes::RefPhaseMax, \ + "Invariant (%d)", phase_number); + +static const char* phase_number_2_string(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number) { + ASSERT_PHASE_NUMBER(phase_number); + + switch(phase_number) { + case ReferenceProcessorPhaseTimes::RefPhase1: + return "Phase1"; + case ReferenceProcessorPhaseTimes::RefPhase2: + return "Phase2"; + case ReferenceProcessorPhaseTimes::RefPhase3: + return "Phase3"; + default: + ShouldNotReachHere(); + return NULL; + } +} + +RefProcParPhaseTimeTracker::RefProcParPhaseTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number, + ReferenceProcessorPhaseTimes* phase_times) : + _phase_number(phase_number), + RefProcPhaseTimeBaseTracker(phase_number_2_string(phase_number), phase_times) {} + +RefProcParPhaseTimeTracker::~RefProcParPhaseTimeTracker() { + double elapsed = elapsed_time(); + ReferenceProcessorPhaseTimes::RefProcParPhases phase = phase_times()->par_phase(_phase_number); + phase_times()->set_par_phase_time_ms(phase, elapsed); +} + +static const char* ref_type_2_string(ReferenceType ref_type) { + ASSERT_REF_TYPE(ref_type); + + switch(ref_type) { + case REF_SOFT: + return "SoftReference"; + case REF_WEAK: + return "WeakReference"; + case REF_FINAL: + return "FinalReference"; + case REF_PHANTOM: + return "PhantomReference"; + default: + ShouldNotReachHere(); + return NULL; + } +} + +RefProcPhaseTimesTracker::RefProcPhaseTimesTracker(ReferenceType ref_type, + ReferenceProcessorPhaseTimes* phase_times, + ReferenceProcessor* rp) : + _rp(rp), RefProcPhaseTimeBaseTracker(ref_type_2_string(ref_type), phase_times) { + phase_times->set_processing_ref_type(ref_type); + + size_t discovered = rp->total_reference_count(ref_type); + phase_times->set_ref_discovered(ref_type, discovered); +} + +RefProcPhaseTimesTracker::~RefProcPhaseTimesTracker() { + double elapsed = elapsed_time(); + ReferenceProcessorPhaseTimes* times = phase_times(); + ReferenceType ref_type = times->processing_ref_type(); + times->set_ref_proc_time_ms(ref_type, elapsed); + + size_t after_count = _rp->total_reference_count(ref_type); + size_t discovered = times->ref_discovered(ref_type); + times->set_ref_cleared(ref_type, discovered - after_count); +} + +RefProcEnqueueTimeTracker::RefProcEnqueueTimeTracker(ReferenceProcessorPhaseTimes* phase_times, + ReferenceProcessorStats& stats) : + RefProcPhaseTimeBaseTracker("Reference Enqueuing", phase_times) { + phase_times->set_ref_enqueued(REF_SOFT, stats.soft_count()); + phase_times->set_ref_enqueued(REF_WEAK, stats.weak_count()); + phase_times->set_ref_enqueued(REF_FINAL, stats.final_count()); + phase_times->set_ref_enqueued(REF_PHANTOM, stats.phantom_count()); +} + +RefProcEnqueueTimeTracker::~RefProcEnqueueTimeTracker() { + double elapsed = elapsed_time(); + + phase_times()->set_par_phase_time_ms(ReferenceProcessorPhaseTimes::RefEnqueue, elapsed); +} + +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)"); + _par_phase_time_ms[i] = uninitialized(); + } + + for (int i = 0; i < number_of_subclasses_of_ref; i++) { + _ref_proc_time_ms[i] = uninitialized(); + _balance_queues_time_ms[i] = uninitialized(); + _ref_cleared[i] = 0; + _ref_discovered[i] = 0; + _ref_enqueued[i] = 0; + } +} + +inline int ref_type_2_index(ReferenceType ref_type) { + return ref_type - REF_SOFT; +} + +#define ASSERT_PAR_PHASE(phase) assert(phase >= ReferenceProcessorPhaseTimes::SoftRefPhase1 && \ + phase < ReferenceProcessorPhaseTimes::RefParPhaseMax, \ + "Invariant (%d)", (int)phase); + +WorkerDataArray* ReferenceProcessorPhaseTimes::worker_time_sec(RefProcParPhases par_phase) const { + ASSERT_PAR_PHASE(par_phase); + return _worker_time_sec[par_phase]; +} + +double ReferenceProcessorPhaseTimes::par_phase_time_ms(RefProcParPhases par_phase) const { + ASSERT_PAR_PHASE(par_phase); + return _par_phase_time_ms[par_phase]; +} + +void ReferenceProcessorPhaseTimes::set_par_phase_time_ms(RefProcParPhases par_phase, + double par_phase_time_ms) { + ASSERT_PAR_PHASE(par_phase); + _par_phase_time_ms[par_phase] = par_phase_time_ms; +} + +void ReferenceProcessorPhaseTimes::reset() { + for (int i = 0; i < RefParPhaseMax; i++) { + _worker_time_sec[i]->reset(); + _par_phase_time_ms[i] = uninitialized(); + } + + for (int i = 0; i < number_of_subclasses_of_ref; i++) { + _ref_proc_time_ms[i] = uninitialized(); + _balance_queues_time_ms[i] = uninitialized(); + _ref_cleared[i] = 0; + _ref_discovered[i] = 0; + _ref_enqueued[i] = 0; + } + + _total_time_ms = uninitialized(); + + _processing_is_mt = false; +} + +ReferenceProcessorPhaseTimes::~ReferenceProcessorPhaseTimes() { + for (int i = 0; i < RefParPhaseMax; i++) { + delete _worker_time_sec[i]; + } +} + +double ReferenceProcessorPhaseTimes::ref_proc_time_ms(ReferenceType ref_type) const { + ASSERT_REF_TYPE(ref_type); + return _par_phase_time_ms[ref_type_2_index(ref_type)]; +} + +void ReferenceProcessorPhaseTimes::set_ref_proc_time_ms(ReferenceType ref_type, + double ref_proc_time_ms) { + ASSERT_REF_TYPE(ref_type); + _ref_proc_time_ms[ref_type_2_index(ref_type)] = ref_proc_time_ms; +} + +size_t ReferenceProcessorPhaseTimes::ref_cleared(ReferenceType ref_type) const { + ASSERT_REF_TYPE(ref_type); + return _ref_cleared[ref_type_2_index(ref_type)]; +} + +void ReferenceProcessorPhaseTimes::set_ref_cleared(ReferenceType ref_type, size_t count) { + ASSERT_REF_TYPE(ref_type); + _ref_cleared[ref_type_2_index(ref_type)] = count; +} + +size_t ReferenceProcessorPhaseTimes::ref_discovered(ReferenceType ref_type) const { + ASSERT_REF_TYPE(ref_type); + return _ref_discovered[ref_type_2_index(ref_type)]; +} + +void ReferenceProcessorPhaseTimes::set_ref_discovered(ReferenceType ref_type, size_t count) { + ASSERT_REF_TYPE(ref_type); + _ref_discovered[ref_type_2_index(ref_type)] = count; +} + +size_t ReferenceProcessorPhaseTimes::ref_enqueued(ReferenceType ref_type) const { + ASSERT_REF_TYPE(ref_type); + return _ref_enqueued[ref_type_2_index(ref_type)]; +} + +void ReferenceProcessorPhaseTimes::set_ref_enqueued(ReferenceType ref_type, size_t count) { + ASSERT_REF_TYPE(ref_type); + _ref_enqueued[ref_type_2_index(ref_type)] = count; +} + +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)]; +} + +void ReferenceProcessorPhaseTimes::set_balance_queues_time_ms(ReferenceType ref_type, double time_ms) { + ASSERT_REF_TYPE(ref_type); + _balance_queues_time_ms[ref_type_2_index(ref_type)] = time_ms; +} + +ReferenceProcessorPhaseTimes::RefProcParPhases +ReferenceProcessorPhaseTimes::par_phase(RefProcPhaseNumbers phase_number) const { + ASSERT_PHASE_NUMBER(phase_number); + ASSERT_REF_TYPE(_processing_ref_type); + + int result = SoftRefPhase1; + + switch(_processing_ref_type) { + case REF_SOFT: + result = (int)SoftRefPhase1; + result += phase_number; + + assert((RefProcParPhases)result >= SoftRefPhase1 && + (RefProcParPhases)result <= SoftRefPhase3, + "Invariant (%d)", result); + break; + case REF_WEAK: + result = (int)WeakRefPhase2; + result += (phase_number - 1); + assert((RefProcParPhases)result >= WeakRefPhase2 && + (RefProcParPhases)result <= WeakRefPhase3, + "Invariant (%d)", result); + break; + case REF_FINAL: + result = (int)FinalRefPhase2; + result += (phase_number - 1); + assert((RefProcParPhases)result >= FinalRefPhase2 && + (RefProcParPhases)result <= FinalRefPhase3, + "Invariant (%d)", result); + break; + case REF_PHANTOM: + result = (int)PhantomRefPhase2; + result += (phase_number - 1); + assert((RefProcParPhases)result >= PhantomRefPhase2 && + (RefProcParPhases)result <= PhantomRefPhase3, + "Invariant (%d)", result); + break; + default: + ShouldNotReachHere(); + } + + ASSERT_PAR_PHASE(result); + + return (RefProcParPhases)result; +} + +void ReferenceProcessorPhaseTimes::print_enqueue_phase(uint base_indent, bool print_total) const { + if (print_total) { + print_phase(RefEnqueue, base_indent); + } + + log_debug(gc, phases, ref)("%sReference Counts: Soft: " SIZE_FORMAT " Weak: " SIZE_FORMAT + " Final: " SIZE_FORMAT " Phantom: " SIZE_FORMAT , + Indents[base_indent + 1], ref_enqueued(REF_SOFT), ref_enqueued(REF_WEAK), + ref_enqueued(REF_FINAL), ref_enqueued(REF_PHANTOM)); +} + +#define TIME_FORMAT "%.1lfms" + +void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) const { + if (print_total) { + LogTarget(Debug, gc, phases, ref) lt; + + if (lt.is_enabled()) { + LogStream ls(lt); + ls.print_cr("%s%s: " TIME_FORMAT, + Indents[base_indent], "Reference Processing", total_time_ms()); + } + } + + uint next_indent = base_indent + 1; + print_reference(REF_SOFT, next_indent); + print_reference(REF_WEAK, next_indent); + print_reference(REF_FINAL, next_indent); + print_reference(REF_PHANTOM, next_indent); +} + +void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) const { + LogTarget(Debug, gc, phases, ref) lt; + + if (lt.is_enabled()) { + LogStream ls(lt); + uint next_indent = base_indent + 1; + ResourceMark rm; + + 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()) { + 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(SoftRefPhase2, next_indent); + print_phase(SoftRefPhase3, next_indent); + break; + + case REF_WEAK: + print_phase(WeakRefPhase2, next_indent); + print_phase(WeakRefPhase3, next_indent); + break; + + case REF_FINAL: + print_phase(FinalRefPhase2, next_indent); + print_phase(FinalRefPhase3, next_indent); + break; + + case REF_PHANTOM: + print_phase(PhantomRefPhase2, next_indent); + print_phase(PhantomRefPhase3, next_indent); + break; + + default: + ShouldNotReachHere(); + } + + 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) const { + double phase_time = par_phase_time_ms(phase); + if (phase_time != uninitialized()) { + LogTarget(Debug, gc, phases, ref) lt; + + LogStream ls(lt); + + 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(&ls, true); + } + } +} + +#undef ASSERT_REF_TYPE +#undef ASSERT_PHASE_NUMBER +#undef ASSERT_PAR_PHASE +#undef TIME_FORMAT