< prev index next >
src/share/vm/gc/shared/referenceProcessorPhaseTimes.cpp
Print this page
rev 13328 : [mq]: webrev.0b
rev 13329 : [mq]: webrev.1
rev 13330 : imported patch webrev.2
rev 13331 : imported patch webrev.3b
rev 13332 : [mq]: webrev.4
*** 25,34 ****
--- 25,35 ----
#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) {
*** 201,214 ****
double elapsed = elapsed_time();
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) {
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();
}
--- 202,213 ----
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();
}
*** 310,364 ****
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(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number) const {
ASSERT_PHASE_NUMBER(phase_number);
ASSERT_REF_TYPE(_processing_ref_type);
! int result = ReferenceProcessorPhaseTimes::SoftRefPhase1;
switch(_processing_ref_type) {
case REF_SOFT:
! result = (int)ReferenceProcessorPhaseTimes::SoftRefPhase1;
result += phase_number;
! assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::SoftRefPhase1 &&
! (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::SoftRefPhase3,
"Invariant (%d)", result);
break;
case REF_WEAK:
! result = (int)ReferenceProcessorPhaseTimes::WeakRefPhase2;
result += (phase_number - 1);
! assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::WeakRefPhase2 &&
! (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::WeakRefPhase3,
"Invariant (%d)", result);
break;
case REF_FINAL:
! result = (int)ReferenceProcessorPhaseTimes::FinalRefPhase2;
result += (phase_number - 1);
! assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::FinalRefPhase2 &&
! (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::FinalRefPhase3,
"Invariant (%d)", result);
break;
case REF_PHANTOM:
! result = (int)ReferenceProcessorPhaseTimes::PhantomRefPhase2;
result += (phase_number - 1);
! assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::PhantomRefPhase2 &&
! (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::PhantomRefPhase3,
"Invariant (%d)", result);
break;
default:
ShouldNotReachHere();
}
--- 309,363 ----
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();
}
*** 366,394 ****
ASSERT_PAR_PHASE(result);
return (RefProcParPhases)result;
}
! void ReferenceProcessorPhaseTimes::print_enqueue_phase(uint base_indent, bool print_total) {
if (print_total) {
! print_phase(ReferenceProcessorPhaseTimes::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) {
if (print_total) {
! Log(gc, phases, ref) log;
! if (log.is_level(LogLevel::Debug)) {
! log.debug_stream()->print_cr("%s%s: " TIME_FORMAT,
Indents[base_indent], "Reference Processing", total_time_ms());
}
}
uint next_indent = base_indent + 1;
--- 365,394 ----
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;
*** 396,468 ****
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) {
! Log(gc, phases, ref) log;
! if (log.is_level(LogLevel::Debug)) {
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));
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);
}
switch(ref_type) {
case REF_SOFT:
print_phase(SoftRefPhase1, next_indent);
! print_phase(ReferenceProcessorPhaseTimes::SoftRefPhase2, next_indent);
! print_phase(ReferenceProcessorPhaseTimes::SoftRefPhase3, next_indent);
break;
case REF_WEAK:
! print_phase(ReferenceProcessorPhaseTimes::WeakRefPhase2, next_indent);
! print_phase(ReferenceProcessorPhaseTimes::WeakRefPhase3, next_indent);
break;
case REF_FINAL:
! print_phase(ReferenceProcessorPhaseTimes::FinalRefPhase2, next_indent);
! print_phase(ReferenceProcessorPhaseTimes::FinalRefPhase3, next_indent);
break;
case REF_PHANTOM:
! print_phase(ReferenceProcessorPhaseTimes::PhantomRefPhase2, next_indent);
! print_phase(ReferenceProcessorPhaseTimes::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));
}
}
! void ReferenceProcessorPhaseTimes::print_phase(RefProcParPhases phase, uint indent) {
double phase_time = par_phase_time_ms(phase);
if (phase_time != uninitialized()) {
! Log(gc, phases, ref) log;
! 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();
! out->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);
}
}
}
#undef ASSERT_REF_TYPE
--- 396,472 ----
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
< prev index next >