< prev index next >
src/share/vm/gc/g1/g1GCPhaseTimes.cpp
Print this page
*** 130,226 ****
_gc_par_phases[i]->verify(_active_gc_threads);
}
}
}
- double G1GCPhaseTimes::info_line(const char* str, double value) {
- log_info(gc, phases)("%s%s: %.1lfms", Indents[1], str, value);
- return value;
- }
-
- void G1GCPhaseTimes::debug_line(const char* str, double value) {
- log_debug(gc, phases)("%s%s: %.1lfms", Indents[2], str, value);
- }
-
- void G1GCPhaseTimes::trace_line(const char* str, double value) {
- log_trace(gc, phases)("%s%s: %.1lfms", Indents[3], str, value);
- }
-
- void G1GCPhaseTimes::trace_line(const char* str, size_t value) {
- log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], str, value);
- }
-
- void G1GCPhaseTimes::trace_phase_tasks(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) {
- LogHandle(gc, phases, task) log;
- if (!log.is_trace()) {
- return;
- }
- ResourceMark rm;
- outputStream* out = log.trace_stream();
- out->print("%s%-25s", indent, "");
- for (uint i = 0; i < _active_gc_threads; ++i) {
- out->print(" %4.1lf", get_time_ms(phase_id, i));
- }
- out->cr();
- }
-
- void G1GCPhaseTimes::trace_phase_counts(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) {
- LogHandle(gc, phases, task) log;
- if (!log.is_trace()) {
- return;
- }
- ResourceMark rm;
- outputStream* out = log.trace_stream();
- out->print("%s%-25s", indent, "");
- for (uint i = 0; i < _active_gc_threads; ++i) {
- out->print(" " SIZE_FORMAT, get_thread_work_item(phase_id, i));
- }
- out->cr();
- }
-
- void G1GCPhaseTimes::debug_phase(G1GCPhaseTimes::GCParPhases phase_id) {
- WorkerDataArray<double>* phase = _gc_par_phases[phase_id];
- log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
- Indents[2], phase->title(),
- min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id),
- max_time_ms(phase_id) - min_time_ms(phase_id), sum_time_ms(phase_id));
- trace_phase_tasks(Indents[2], phase_id);
- if (phase->thread_work_items() != NULL) {
- log_debug(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT,
- Indents[3], phase->thread_work_items()->title(),
- min_thread_work_items(phase_id), average_thread_work_items(phase_id), max_thread_work_items(phase_id),
- max_thread_work_items(phase_id) - min_thread_work_items(phase_id), sum_thread_work_items(phase_id));
- trace_phase_counts(Indents[3], phase_id);
- }
- }
-
- void G1GCPhaseTimes::trace_phase(G1GCPhaseTimes::GCParPhases phase_id) {
- WorkerDataArray<double>* phase = _gc_par_phases[phase_id];
- log_trace(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
- Indents[3], phase->title(),
- min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id),
- max_time_ms(phase_id) - min_time_ms(phase_id), sum_time_ms(phase_id));
- trace_phase_tasks(Indents[3], phase_id);
- if (phase->thread_work_items() != NULL) {
- log_trace(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT,
- Indents[4], phase->thread_work_items()->title(),
- min_thread_work_items(phase_id), average_thread_work_items(phase_id), max_thread_work_items(phase_id),
- max_thread_work_items(phase_id) - min_thread_work_items(phase_id), sum_thread_work_items(phase_id));
- trace_phase_counts(Indents[4], phase_id);
- }
- }
-
- void G1GCPhaseTimes::trace_phase_no_sum(G1GCPhaseTimes::GCParPhases phase_id) {
- WorkerDataArray<double>* phase = _gc_par_phases[phase_id];
- log_trace(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf",
- Indents[3], phase->title(),
- min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id),
- max_time_ms(phase_id) - min_time_ms(phase_id));
- trace_phase_tasks(Indents[3], phase_id);
- assert(phase->thread_work_items() == NULL, "work_items not implemented for no_sum.");
- }
-
// record the time a phase took in seconds
void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
_gc_par_phases[phase]->set(worker_i, secs);
}
--- 130,139 ----
*** 236,326 ****
// return the average time for a phase in milliseconds
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
}
! double G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) {
! return _gc_par_phases[phase]->get(worker_i) * 1000.0;
}
! double G1GCPhaseTimes::sum_time_ms(GCParPhases phase) {
! return _gc_par_phases[phase]->sum(_active_gc_threads) * 1000.0;
}
! double G1GCPhaseTimes::min_time_ms(GCParPhases phase) {
! return _gc_par_phases[phase]->minimum(_active_gc_threads) * 1000.0;
! }
! double G1GCPhaseTimes::max_time_ms(GCParPhases phase) {
! return _gc_par_phases[phase]->maximum(_active_gc_threads) * 1000.0;
}
! size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i) {
! assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->get(worker_i);
}
! size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
! assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
}
! double G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) {
! assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->average(_active_gc_threads);
! }
! size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {
! assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads);
! }
! size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {
! assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads);
! }
void G1GCPhaseTimes::print() {
note_gc_end();
double accounted_time_ms = _external_accounted_time_ms;
if (_root_region_scan_wait_time_ms > 0.0) {
! accounted_time_ms += info_line("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
! accounted_time_ms += info_line("Evacuate Collection Set", _cur_collection_par_time_ms);
! trace_phase_no_sum(GCWorkerStart);
! debug_phase(ExtRootScan);
for (int i = ThreadRoots; i <= SATBFiltering; i++) {
! trace_phase((GCParPhases) i);
}
! debug_phase(UpdateRS);
if (ConcurrentG1Refine::hot_card_cache_enabled()) {
! trace_phase(ScanHCC);
}
! debug_phase(ScanRS);
! debug_phase(CodeRoots);
! debug_phase(ObjCopy);
! debug_phase(Termination);
! debug_phase(Other);
! debug_phase(GCWorkerTotal);
! trace_phase_no_sum(GCWorkerEnd);
! accounted_time_ms += info_line("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms);
debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
if (G1StringDedup::is_enabled()) {
! accounted_time_ms += info_line("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
! debug_phase(StringDedupQueueFixup);
! debug_phase(StringDedupTableFixup);
}
! accounted_time_ms += info_line("Clear Card Table", _cur_clear_ct_time_ms);
! accounted_time_ms += info_line("Expand Heap After Collection", _cur_expand_heap_time_ms);
double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms;
! accounted_time_ms += info_line("Free Collection Set", free_cset_time);
debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms);
debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms);
info_line("Other", _gc_pause_time_ms - accounted_time_ms);
if (_cur_verify_before_time_ms > 0.0) {
--- 149,264 ----
// return the average time for a phase in milliseconds
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
}
! size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
! assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
}
! template <class T>
! void G1GCPhaseTimes::details(T* phase, const char* indent) {
! LogHandle(gc, phases, task) log;
! if (log.is_level(LogLevel::Trace)) {
! outputStream* trace_out = log.trace_stream();
! trace_out->print("%s", indent);
! phase->print_details_on(trace_out, _active_gc_threads);
! }
}
! void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
! out->print("%s", Indents[indent]);
! phase->print_summary_on(out, _active_gc_threads, print_sum);
! details(phase, Indents[indent]);
! WorkerDataArray<size_t>* work_items = phase->thread_work_items();
! if (work_items != NULL) {
! out->print("%s", Indents[indent + 1]);
! work_items->print_summary_on(out, _active_gc_threads, true);
! details(work_items, Indents[indent + 1]);
! }
}
! void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
! LogHandle(gc, phases) log;
! if (log.is_level(LogLevel::Debug)) {
! ResourceMark rm;
! log_phase(phase, 2, log.debug_stream(), true);
! }
}
! void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) {
! LogHandle(gc, phases) log;
! if (log.is_level(LogLevel::Trace)) {
! ResourceMark rm;
! log_phase(phase, 3, log.trace_stream(), print_sum);
! }
}
! #define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms"
! #define PHASE_SIZE_FORMAT "%s%s: " SIZE_FORMAT
! #define info_line(str, value) \
! log_info(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[1], str, value);
! #define debug_line(str, value) \
! log_debug(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[2], str, value);
!
! #define trace_line(str, value) \
! log_trace(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[3], str, value);
!
! #define trace_line_sz(str, value) \
! log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);
!
! #define trace_line_ms(str, value) \
! log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);
!
! #define info_line_and_account(str, value) \
! info_line(str, value); \
! accounted_time_ms += value;
void G1GCPhaseTimes::print() {
note_gc_end();
double accounted_time_ms = _external_accounted_time_ms;
if (_root_region_scan_wait_time_ms > 0.0) {
! info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
! info_line_and_account("Evacuate Collection Set", _cur_collection_par_time_ms);
! trace_phase(_gc_par_phases[GCWorkerStart], false);
! debug_phase(_gc_par_phases[ExtRootScan]);
for (int i = ThreadRoots; i <= SATBFiltering; i++) {
! trace_phase(_gc_par_phases[i]);
}
! debug_phase(_gc_par_phases[UpdateRS]);
if (ConcurrentG1Refine::hot_card_cache_enabled()) {
! trace_phase(_gc_par_phases[ScanHCC]);
}
! debug_phase(_gc_par_phases[ScanRS]);
! debug_phase(_gc_par_phases[CodeRoots]);
! debug_phase(_gc_par_phases[ObjCopy]);
! debug_phase(_gc_par_phases[Termination]);
! debug_phase(_gc_par_phases[Other]);
! debug_phase(_gc_par_phases[GCWorkerTotal]);
! trace_phase(_gc_par_phases[GCWorkerEnd], false);
! info_line_and_account("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms);
debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
if (G1StringDedup::is_enabled()) {
! info_line_and_account("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
! debug_phase(_gc_par_phases[StringDedupQueueFixup]);
! debug_phase(_gc_par_phases[StringDedupTableFixup]);
}
! info_line_and_account("Clear Card Table", _cur_clear_ct_time_ms);
! info_line_and_account("Expand Heap After Collection", _cur_expand_heap_time_ms);
double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms;
! info_line_and_account("Free Collection Set", free_cset_time);
debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms);
debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms);
info_line("Other", _gc_pause_time_ms - accounted_time_ms);
if (_cur_verify_before_time_ms > 0.0) {
*** 336,352 ****
}
debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
debug_line("Ref Proc", _cur_ref_proc_time_ms);
debug_line("Ref Enq", _cur_ref_enq_time_ms);
debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
! trace_phase(RedirtyCards);
if (G1EagerReclaimHumongousObjects) {
debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
! trace_line("Humongous Total", _cur_fast_reclaim_humongous_total);
! trace_line("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
! trace_line("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
}
if (_cur_verify_after_time_ms > 0.0) {
debug_line("Verify After", _cur_verify_after_time_ms);
}
}
--- 274,290 ----
}
debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
debug_line("Ref Proc", _cur_ref_proc_time_ms);
debug_line("Ref Enq", _cur_ref_enq_time_ms);
debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
! trace_phase(_gc_par_phases[RedirtyCards]);
if (G1EagerReclaimHumongousObjects) {
debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
! trace_line_sz("Humongous Total", _cur_fast_reclaim_humongous_total);
! trace_line_sz("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
! trace_line_sz("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
}
if (_cur_verify_after_time_ms > 0.0) {
debug_line("Verify After", _cur_verify_after_time_ms);
}
}
< prev index next >