--- old/src/share/vm/gc/g1/g1GCPhaseTimes.cpp 2016-02-26 12:38:13.993399306 +0100 +++ new/src/share/vm/gc/g1/g1GCPhaseTimes.cpp 2016-02-26 12:38:13.873399301 +0100 @@ -132,93 +132,6 @@ } } -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* 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* 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* 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); @@ -238,87 +151,112 @@ 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; +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::sum_time_ms(GCParPhases phase) { - return _gc_par_phases[phase]->sum(_active_gc_threads) * 1000.0; +template +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); + } } -double G1GCPhaseTimes::min_time_ms(GCParPhases phase) { - return _gc_par_phases[phase]->minimum(_active_gc_threads) * 1000.0; -} +void G1GCPhaseTimes::log_phase(WorkerDataArray* 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]); -double G1GCPhaseTimes::max_time_ms(GCParPhases phase) { - return _gc_par_phases[phase]->maximum(_active_gc_threads) * 1000.0; + WorkerDataArray* 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]); + } } -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); +void G1GCPhaseTimes::debug_phase(WorkerDataArray* phase) { + LogHandle(gc, phases) log; + if (log.is_level(LogLevel::Debug)) { + ResourceMark rm; + log_phase(phase, 2, log.debug_stream(), true); + } } -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); +void G1GCPhaseTimes::trace_phase(WorkerDataArray* 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); + } } -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); -} +#define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms" +#define PHASE_SIZE_FORMAT "%s%s: " SIZE_FORMAT -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); -} +#define info_line(str, value) \ + log_info(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[1], str, value); -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); -} +#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) { - accounted_time_ms += info_line("Root Region Scan Waiting", _root_region_scan_wait_time_ms); + info_line_and_account("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); + 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((GCParPhases) i); + trace_phase(_gc_par_phases[i]); } - debug_phase(UpdateRS); + debug_phase(_gc_par_phases[UpdateRS]); if (ConcurrentG1Refine::hot_card_cache_enabled()) { - trace_phase(ScanHCC); + trace_phase(_gc_par_phases[ScanHCC]); } - debug_phase(ScanRS); - debug_phase(CodeRoots); - debug_phase(ObjCopy); - debug_phase(Termination); - debug_phase(Other); - debug_phase(GCWorkerTotal); - trace_phase_no_sum(GCWorkerEnd); + 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); - accounted_time_ms += info_line("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms); + 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()) { - accounted_time_ms += info_line("String Dedup Fixup", _cur_string_dedup_fixup_time_ms); - debug_phase(StringDedupQueueFixup); - debug_phase(StringDedupTableFixup); + 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]); } - 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); + 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; - accounted_time_ms += info_line("Free Collection Set", free_cset_time); + 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); @@ -338,13 +276,13 @@ 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); + trace_phase(_gc_par_phases[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); + 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("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); + 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);