--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/gc/shared/referenceProcessorPhaseTimes.cpp Thu Aug 10 18:09:19 2017 -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<double>(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<double>* 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