--- /dev/null 2017-06-09 15:42:47.034680681 -0700 +++ new/src/share/vm/gc/shared/referenceProcessorPhaseTimes.cpp 2017-06-09 16:48:19.484192891 -0700 @@ -0,0 +1,239 @@ +/* + * 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" + +RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(WorkerDataArray* worker_time, uint worker_id) : + _worker_time(worker_time), _start_time(0.0), _worker_id(worker_id) { + if (_worker_time != NULL) { + _start_time = os::elapsedTime(); + } +} + +RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() { + if (_worker_time != NULL) { + _worker_time->set(_worker_id, os::elapsedTime() - _start_time); + } +} + +static size_t total_count_from_list(DiscoveredList lists[], uint max_num_q) { + size_t total = 0; + for (uint i = 0; i < max_num_q; ++i) { + total += lists[i].length(); + } + return total; +} + +RefProcPhaseTimeBaseTracker::RefProcPhaseTimeBaseTracker(const char* title, + ReferenceProcessorPhaseTimes* phase_times, + GCTimer* gc_timer) : + _title(title), _phase_times(phase_times), _start_ticks(), _end_ticks(), _gc_timer(gc_timer) { + assert(_phase_times != NULL, "Invariant"); + + _start_ticks.stamp(); + if (_gc_timer != NULL) { + _gc_timer->register_gc_phase_start(_title, _start_ticks); + } +} + +static const char* phase_enum_2_string(ReferenceProcessorPhaseTimes::RefProcPhases phase) { + switch(phase) { + case ReferenceProcessorPhaseTimes::RefPhase1: + return "Phase1"; + case ReferenceProcessorPhaseTimes::RefPhase2: + return "Phase2"; + case ReferenceProcessorPhaseTimes::RefPhase3: + return "Phase3"; + case ReferenceProcessorPhaseTimes::RefEnqueue: + return "Enqueue reference lists"; + default: + ShouldNotReachHere(); + return NULL; + } +} + +static const char* Indents[5] = {"", " ", " ", " ", " "}; + +void RefProcPhaseTimeBaseTracker::print_phase(ReferenceProcessorPhaseTimes::RefProcPhases phase, uint indent) { + double phase_time = phase_times()->phase_time_ms(phase); + if (phase_time != ReferenceProcessorPhaseTimes::uninitialized()) { + Log(gc, ref) log; + + log.debug_stream()->print_cr("%s%s%s %0.3fms", + Indents[indent], + phase_enum_2_string(phase), + indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */ + phase_time); + if (phase_times()->processing_is_mt() && log.is_level(LogLevel::Trace)) { + outputStream* out = log.trace_stream(); + + out->print("%s", " "); + // worker_time_sec is recorded in seconds but it will be printed in milliseconds. + phase_times()->worker_time_sec(phase)->print_summary_on(out, true); + } + } +} + +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 (_gc_timer != NULL) { + Ticks ticks = end_ticks(); + _gc_timer->register_gc_phase_end(ticks); + } +} + +RefProcBalanceQueuesTimeTracker::RefProcBalanceQueuesTimeTracker(ReferenceProcessorPhaseTimes* phase_times, + GCTimer* gc_timer) : + RefProcPhaseTimeBaseTracker("Balance queues", phase_times, gc_timer) {} + +RefProcBalanceQueuesTimeTracker::~RefProcBalanceQueuesTimeTracker() { + double elapsed = elapsed_time(); + phase_times()->set_balance_queues_time_ms(elapsed); +} + +RefProcPhaseTimeTracker::RefProcPhaseTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhases phase, + ReferenceProcessorPhaseTimes* phase_times, + GCTimer* gc_timer) : + _phase(phase), RefProcPhaseTimeBaseTracker(phase_enum_2_string(phase), phase_times, gc_timer) {} + +RefProcPhaseTimeTracker::~RefProcPhaseTimeTracker() { + double elapsed = elapsed_time(); + phase_times()->set_phase_time_ms(_phase, elapsed); +} + +RefProcPhaseTimesLogger::RefProcPhaseTimesLogger(const char* title, + ReferenceProcessorPhaseTimes* times, + DiscoveredList lists[], + GCTimer* gc_timer) : + _lists(lists), RefProcPhaseTimeBaseTracker(title, times, gc_timer) { + _ref_discovered = total_count_from_list(_lists, phase_times()->max_gc_threads()); +} + +RefProcPhaseTimesLogger::~RefProcPhaseTimesLogger() { + double elapsed = elapsed_time(); + + Log(gc, ref) log; + + if (log.is_level(LogLevel::Debug)) { + outputStream* out = log.debug_stream(); + ResourceMark rm; + + out->print_cr("%s %0.3fms", _title, elapsed); + + double balance_time = phase_times()->balance_queues_time_ms(); + if (balance_time != ReferenceProcessorPhaseTimes::uninitialized()) { + out->print_cr(" %s %0.3fms", "Balance queues:", balance_time); + } + + // Print stats + print_phase(ReferenceProcessorPhaseTimes::RefPhase1, 1); + print_phase(ReferenceProcessorPhaseTimes::RefPhase2, 1); + print_phase(ReferenceProcessorPhaseTimes::RefPhase3, 1); + + size_t after_count = total_count_from_list(_lists, phase_times()->max_gc_threads()); + out->print_cr(" %s " SIZE_FORMAT, "Cleared:", _ref_discovered - after_count); + out->print_cr(" %s " SIZE_FORMAT, "Discovered:", _ref_discovered); + } + + // Reset for next use. + phase_times()->reset(); +} + +RefProcEnqueueTimeLogger::RefProcEnqueueTimeLogger(ReferenceProcessorPhaseTimes* phase_times, + ReferenceProcessorStats& stats, + GCTimer* gc_timer) : + _stats(stats), RefProcPhaseTimeBaseTracker("Enqueue reference lists", phase_times, gc_timer) {} + +RefProcEnqueueTimeLogger::~RefProcEnqueueTimeLogger() { + double elapsed = elapsed_time(); + + phase_times()->set_phase_time_ms(ReferenceProcessorPhaseTimes::RefEnqueue, elapsed); + + print_phase(ReferenceProcessorPhaseTimes::RefEnqueue, 0); + phase_times()->reset(); + + log_debug(gc, ref)(" Counts: Soft: " SIZE_FORMAT " Weak: " SIZE_FORMAT + " Final: " SIZE_FORMAT " Phantom: " SIZE_FORMAT , + _stats.soft_count(), _stats.weak_count(), + _stats.final_count(), _stats.phantom_count()); +} + +ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(uint max_gc_threads, bool processing_is_mt) : + _balance_queues_time_ms(uninitialized()), _max_gc_threads(max_gc_threads), _processing_is_mt(processing_is_mt) { + + _worker_time_sec[RefPhase1] = new WorkerDataArray(_max_gc_threads, "Process lists (ms)"); + _worker_time_sec[RefPhase2] = new WorkerDataArray(_max_gc_threads, "Process lists (ms)"); + _worker_time_sec[RefPhase3] = new WorkerDataArray(_max_gc_threads, "Process lists (ms)"); + _worker_time_sec[RefEnqueue] = new WorkerDataArray(_max_gc_threads, "Process lists (ms)"); + + _phase_time_ms[RefPhase1] = uninitialized(); + _phase_time_ms[RefPhase2] = uninitialized(); + _phase_time_ms[RefPhase3] = uninitialized(); + _phase_time_ms[RefEnqueue] = uninitialized(); +} + +WorkerDataArray* ReferenceProcessorPhaseTimes::worker_time_sec(RefProcPhases phase) const { + assert(phase >= RefPhase1 && phase < RefPhaseMax, "Invariant"); + return _worker_time_sec[phase]; +} + +double ReferenceProcessorPhaseTimes::phase_time_ms(RefProcPhases phase) const { + assert(phase >= RefPhase1 && phase < RefPhaseMax, "Invariant"); + return _phase_time_ms[phase]; +} + +void ReferenceProcessorPhaseTimes::set_phase_time_ms(RefProcPhases phase, double phase_time_ms) { + assert(phase >= RefPhase1 && phase < RefPhaseMax, "Invariant"); + _phase_time_ms[phase] = phase_time_ms; +} + +void ReferenceProcessorPhaseTimes::reset() { + for (int i = 0; i < RefPhaseMax; i++) { + _worker_time_sec[i]->reset(); + _phase_time_ms[i] = uninitialized(); + } + + _balance_queues_time_ms = uninitialized(); + + _processing_is_mt = false; +} +