mirror of
https://github.com/openjdk/jdk.git
synced 2026-03-04 05:00:31 +00:00
8167679: G1 phase logging is messy
Reviewed-by: sjohanss, tschatzl
This commit is contained in:
Erik Helin
parent
c5b56dab55
commit
d19575bfac
@ -218,7 +218,7 @@ size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
|
||||
}
|
||||
|
||||
template <class T>
|
||||
void G1GCPhaseTimes::details(T* phase, const char* indent) {
|
||||
void G1GCPhaseTimes::details(T* phase, const char* indent) const {
|
||||
Log(gc, phases, task) log;
|
||||
if (log.is_level(LogLevel::Trace)) {
|
||||
outputStream* trace_out = log.trace_stream();
|
||||
@ -227,7 +227,7 @@ void G1GCPhaseTimes::details(T* phase, const char* indent) {
|
||||
}
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
|
||||
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
|
||||
out->print("%s", Indents[indent]);
|
||||
phase->print_summary_on(out, print_sum);
|
||||
details(phase, Indents[indent]);
|
||||
@ -240,7 +240,7 @@ void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outp
|
||||
}
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
|
||||
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) const {
|
||||
Log(gc, phases) log;
|
||||
if (log.is_level(LogLevel::Debug)) {
|
||||
ResourceMark rm;
|
||||
@ -248,7 +248,7 @@ void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
|
||||
}
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) {
|
||||
void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
|
||||
Log(gc, phases) log;
|
||||
if (log.is_level(LogLevel::Trace)) {
|
||||
ResourceMark rm;
|
||||
@ -256,37 +256,50 @@ void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum)
|
||||
}
|
||||
}
|
||||
|
||||
#define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms"
|
||||
#define PHASE_SIZE_FORMAT "%s%s: " SIZE_FORMAT
|
||||
#define TIME_FORMAT "%.1lfms"
|
||||
|
||||
#define info_line(str, value) \
|
||||
log_info(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[1], str, value);
|
||||
void G1GCPhaseTimes::info_time(const char* name, double value) const {
|
||||
log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
|
||||
}
|
||||
|
||||
#define debug_line(str, value) \
|
||||
log_debug(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[2], str, value);
|
||||
void G1GCPhaseTimes::debug_time(const char* name, double value) const {
|
||||
log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
|
||||
}
|
||||
|
||||
#define trace_line(str, value) \
|
||||
log_trace(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[3], str, value);
|
||||
void G1GCPhaseTimes::trace_time(const char* name, double value) const {
|
||||
log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
|
||||
}
|
||||
|
||||
#define trace_line_sz(str, value) \
|
||||
log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);
|
||||
void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
|
||||
log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
|
||||
}
|
||||
|
||||
#define trace_line_ms(str, value) \
|
||||
log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);
|
||||
double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
|
||||
const double sum_ms = _root_region_scan_wait_time_ms +
|
||||
_recorded_young_cset_choice_time_ms +
|
||||
_recorded_non_young_cset_choice_time_ms +
|
||||
_cur_fast_reclaim_humongous_register_time_ms;
|
||||
|
||||
#define info_line_and_account(str, value) \
|
||||
info_line(str, value); \
|
||||
accounted_time_ms += value;
|
||||
info_time("Pre Evacuate Collection Set", sum_ms);
|
||||
|
||||
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);
|
||||
debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
|
||||
}
|
||||
debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
|
||||
if (G1EagerReclaimHumongousObjects) {
|
||||
debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
|
||||
trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
|
||||
trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
|
||||
}
|
||||
|
||||
info_line_and_account("Evacuate Collection Set", _cur_collection_par_time_ms);
|
||||
return sum_ms;
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::print_evacuate_collection_set() const {
|
||||
const double sum_ms = _cur_collection_par_time_ms;
|
||||
|
||||
info_time("Evacuate Collection Set", sum_ms);
|
||||
|
||||
trace_phase(_gc_par_phases[GCWorkerStart], false);
|
||||
debug_phase(_gc_par_phases[ExtRootScan]);
|
||||
for (int i = ThreadRoots; i <= SATBFiltering; i++) {
|
||||
@ -304,57 +317,98 @@ void G1GCPhaseTimes::print() {
|
||||
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);
|
||||
return sum_ms;
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
|
||||
const double evac_fail_handling = _cur_evac_fail_recalc_used +
|
||||
_cur_evac_fail_remove_self_forwards +
|
||||
_cur_evac_fail_restore_remsets;
|
||||
const double sum_ms = evac_fail_handling +
|
||||
_cur_collection_code_root_fixup_time_ms +
|
||||
_recorded_preserve_cm_referents_time_ms +
|
||||
_cur_ref_proc_time_ms +
|
||||
_cur_ref_enq_time_ms +
|
||||
_cur_clear_ct_time_ms +
|
||||
_recorded_merge_pss_time_ms +
|
||||
_cur_strong_code_root_purge_time_ms +
|
||||
_recorded_redirty_logged_cards_time_ms +
|
||||
_recorded_clear_claimed_marks_time_ms +
|
||||
_recorded_total_free_cset_time_ms +
|
||||
_cur_fast_reclaim_humongous_time_ms +
|
||||
_cur_expand_heap_time_ms +
|
||||
_cur_string_dedup_fixup_time_ms;
|
||||
|
||||
info_time("Post Evacuate Collection Set", sum_ms);
|
||||
|
||||
debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
|
||||
|
||||
debug_time("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
|
||||
trace_phase(_gc_par_phases[PreserveCMReferents]);
|
||||
|
||||
debug_time("Reference Processing", _cur_ref_proc_time_ms);
|
||||
|
||||
if (G1StringDedup::is_enabled()) {
|
||||
info_line_and_account("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
|
||||
debug_time("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);
|
||||
|
||||
info_line_and_account("Free Collection Set", _recorded_total_free_cset_time_ms);
|
||||
debug_line("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
|
||||
debug_phase(_gc_par_phases[YoungFreeCSet]);
|
||||
debug_phase(_gc_par_phases[NonYoungFreeCSet]);
|
||||
debug_time("Clear Card Table", _cur_clear_ct_time_ms);
|
||||
|
||||
info_line_and_account("Merge Per-Thread State", _recorded_merge_pss_time_ms);
|
||||
|
||||
info_line("Other", _gc_pause_time_ms - accounted_time_ms);
|
||||
if (_cur_verify_before_time_ms > 0.0) {
|
||||
debug_line("Verify Before", _cur_verify_before_time_ms);
|
||||
}
|
||||
if (G1CollectedHeap::heap()->evacuation_failed()) {
|
||||
double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
|
||||
_cur_evac_fail_restore_remsets;
|
||||
debug_line("Evacuation Failure", evac_fail_handling);
|
||||
trace_line("Recalculate Used", _cur_evac_fail_recalc_used);
|
||||
trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
|
||||
trace_line("Restore RemSet", _cur_evac_fail_restore_remsets);
|
||||
debug_time("Evacuation Failure", evac_fail_handling);
|
||||
trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
|
||||
trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
|
||||
trace_time("Restore RemSet", _cur_evac_fail_restore_remsets);
|
||||
}
|
||||
debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
|
||||
debug_line("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
|
||||
trace_phase(_gc_par_phases[PreserveCMReferents]);
|
||||
debug_line("Reference Processing", _cur_ref_proc_time_ms);
|
||||
debug_line("Reference Enqueuing", _cur_ref_enq_time_ms);
|
||||
debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
|
||||
|
||||
debug_time("Reference Enqueuing", _cur_ref_enq_time_ms);
|
||||
|
||||
debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
|
||||
debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
|
||||
|
||||
debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
|
||||
if (_recorded_clear_claimed_marks_time_ms > 0.0) {
|
||||
debug_line("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
|
||||
debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
|
||||
}
|
||||
|
||||
trace_phase(_gc_par_phases[RedirtyCards]);
|
||||
|
||||
debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
|
||||
trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
|
||||
trace_phase(_gc_par_phases[YoungFreeCSet]);
|
||||
trace_phase(_gc_par_phases[NonYoungFreeCSet]);
|
||||
|
||||
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);
|
||||
debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
|
||||
trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
|
||||
}
|
||||
debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
|
||||
|
||||
|
||||
return sum_ms;
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::print_other(double accounted_ms) const {
|
||||
info_time("Other", _gc_pause_time_ms - accounted_ms);
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::print() {
|
||||
note_gc_end();
|
||||
|
||||
if (_cur_verify_before_time_ms > 0.0) {
|
||||
debug_time("Verify Before", _cur_verify_before_time_ms);
|
||||
}
|
||||
|
||||
double accounted_ms = 0.0;
|
||||
accounted_ms += print_pre_evacuate_collection_set();
|
||||
accounted_ms += print_evacuate_collection_set();
|
||||
accounted_ms += print_post_evacuate_collection_set();
|
||||
print_other(accounted_ms);
|
||||
|
||||
if (_cur_verify_after_time_ms > 0.0) {
|
||||
debug_line("Verify After", _cur_verify_after_time_ms);
|
||||
debug_time("Verify After", _cur_verify_after_time_ms);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -25,6 +25,7 @@
|
||||
#ifndef SHARE_VM_GC_G1_G1GCPHASETIMES_HPP
|
||||
#define SHARE_VM_GC_G1_G1GCPHASETIMES_HPP
|
||||
|
||||
#include "logging/logLevel.hpp"
|
||||
#include "memory/allocation.hpp"
|
||||
|
||||
class LineBuffer;
|
||||
@ -132,10 +133,21 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
|
||||
void reset();
|
||||
|
||||
template <class T>
|
||||
void details(T* phase, const char* indent);
|
||||
void log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum);
|
||||
void debug_phase(WorkerDataArray<double>* phase);
|
||||
void trace_phase(WorkerDataArray<double>* phase, bool print_sum = true);
|
||||
void details(T* phase, const char* indent) const;
|
||||
|
||||
void log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const;
|
||||
void debug_phase(WorkerDataArray<double>* phase) const;
|
||||
void trace_phase(WorkerDataArray<double>* phase, bool print_sum = true) const;
|
||||
|
||||
void info_time(const char* name, double value) const;
|
||||
void debug_time(const char* name, double value) const;
|
||||
void trace_time(const char* name, double value) const;
|
||||
void trace_count(const char* name, size_t value) const;
|
||||
|
||||
double print_pre_evacuate_collection_set() const;
|
||||
double print_evacuate_collection_set() const;
|
||||
double print_post_evacuate_collection_set() const;
|
||||
void print_other(double accounted_ms) const;
|
||||
|
||||
public:
|
||||
G1GCPhaseTimes(uint max_gc_threads);
|
||||
|
||||
@ -73,6 +73,11 @@ public class TestGCLogMessages {
|
||||
};
|
||||
|
||||
private LogMessageWithLevel allLogMessages[] = new LogMessageWithLevel[] {
|
||||
new LogMessageWithLevel("Pre Evacuate Collection Set", Level.INFO),
|
||||
new LogMessageWithLevel("Evacuate Collection Set", Level.INFO),
|
||||
new LogMessageWithLevel("Post Evacuate Collection Set", Level.INFO),
|
||||
new LogMessageWithLevel("Other", Level.INFO),
|
||||
|
||||
// Update RS
|
||||
new LogMessageWithLevel("Scan HCC", Level.TRACE),
|
||||
// Ext Root Scan
|
||||
@ -96,20 +101,20 @@ public class TestGCLogMessages {
|
||||
new LogMessageWithLevel("Redirtied Cards", Level.TRACE),
|
||||
// Misc Top-level
|
||||
new LogMessageWithLevel("Code Roots Purge", Level.DEBUG),
|
||||
new LogMessageWithLevel("String Dedup Fixup", Level.INFO),
|
||||
new LogMessageWithLevel("Expand Heap After Collection", Level.INFO),
|
||||
new LogMessageWithLevel("String Dedup Fixup", Level.DEBUG),
|
||||
new LogMessageWithLevel("Expand Heap After Collection", Level.DEBUG),
|
||||
// Free CSet
|
||||
new LogMessageWithLevel("Free Collection Set", Level.INFO),
|
||||
new LogMessageWithLevel("Free Collection Set Serial", Level.DEBUG),
|
||||
new LogMessageWithLevel("Young Free Collection Set", Level.DEBUG),
|
||||
new LogMessageWithLevel("Non-Young Free Collection Set", Level.DEBUG),
|
||||
new LogMessageWithLevel("Free Collection Set", Level.DEBUG),
|
||||
new LogMessageWithLevel("Free Collection Set Serial", Level.TRACE),
|
||||
new LogMessageWithLevel("Young Free Collection Set", Level.TRACE),
|
||||
new LogMessageWithLevel("Non-Young Free Collection Set", Level.TRACE),
|
||||
// Humongous Eager Reclaim
|
||||
new LogMessageWithLevel("Humongous Reclaim", Level.DEBUG),
|
||||
new LogMessageWithLevel("Humongous Register", Level.DEBUG),
|
||||
// Preserve CM Referents
|
||||
new LogMessageWithLevel("Preserve CM Refs", Level.DEBUG),
|
||||
// Merge PSS
|
||||
new LogMessageWithLevel("Merge Per-Thread State", Level.INFO),
|
||||
new LogMessageWithLevel("Merge Per-Thread State", Level.DEBUG),
|
||||
};
|
||||
|
||||
void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception {
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user