8152100: Rework and unify the GC phase logging

Reviewed-by: sjohanss, jwilhelm
This commit is contained in:
Stefan Karlsson 2016-03-18 08:59:07 +01:00
parent 9682b4de13
commit a15383123d
12 changed files with 117 additions and 117 deletions

View file

@ -195,10 +195,10 @@ const char* PSParallelCompact::space_names[] = {
};
void PSParallelCompact::print_region_ranges() {
if (!log_develop_is_enabled(Trace, gc, compaction, phases)) {
if (!log_develop_is_enabled(Trace, gc, compaction)) {
return;
}
LogHandle(gc, compaction, phases) log;
LogHandle(gc, compaction) log;
ResourceMark rm;
Universe::print_on(log.trace_stream());
log.trace("space bottom top end new_top");
@ -225,7 +225,7 @@ print_generic_summary_region(size_t i, const ParallelCompactData::RegionData* c)
ParallelCompactData& sd = PSParallelCompact::summary_data();
size_t dci = c->destination() ? sd.addr_to_region_idx(c->destination()) : 0;
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
REGION_IDX_FORMAT " " PTR_FORMAT " "
REGION_IDX_FORMAT " " PTR_FORMAT " "
REGION_DATA_FORMAT " " REGION_DATA_FORMAT " "
@ -258,14 +258,14 @@ print_generic_summary_data(ParallelCompactData& summary_data,
++i;
}
log_develop_trace(gc, compaction, phases)("summary_data_bytes=" SIZE_FORMAT, total_words * HeapWordSize);
log_develop_trace(gc, compaction)("summary_data_bytes=" SIZE_FORMAT, total_words * HeapWordSize);
}
void
print_generic_summary_data(ParallelCompactData& summary_data,
SpaceInfo* space_info)
{
if (!log_develop_is_enabled(Trace, gc, compaction, phases)) {
if (!log_develop_is_enabled(Trace, gc, compaction)) {
return;
}
@ -296,7 +296,7 @@ print_initial_summary_data(ParallelCompactData& summary_data,
size_t i = summary_data.addr_to_region_idx(space->bottom());
while (i < end_region && summary_data.region(i)->data_size() == region_size) {
ParallelCompactData::RegionData* c = summary_data.region(i);
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
SIZE_FORMAT_W(5) " " PTR_FORMAT " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " %d",
i, p2i(c->destination()),
c->partial_obj_size(), c->live_obj_size(),
@ -330,7 +330,7 @@ print_initial_summary_data(ParallelCompactData& summary_data,
}
ParallelCompactData::RegionData* c = summary_data.region(i);
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
SIZE_FORMAT_W(5) " " PTR_FORMAT " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " %d"
"%12.10f " SIZE_FORMAT_W(10) " " SIZE_FORMAT_W(10),
i, p2i(c->destination()),
@ -346,21 +346,21 @@ print_initial_summary_data(ParallelCompactData& summary_data,
// Any remaining regions are empty. Print one more if there is one.
if (i < end_region) {
ParallelCompactData::RegionData* c = summary_data.region(i);
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
SIZE_FORMAT_W(5) " " PTR_FORMAT " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " " SIZE_FORMAT_W(5) " %d",
i, p2i(c->destination()),
c->partial_obj_size(), c->live_obj_size(),
c->data_size(), c->source_region(), c->destination_count());
}
log_develop_trace(gc, compaction, phases)("max: " SIZE_FORMAT_W(4) " d2r=" SIZE_FORMAT_W(10) " l2r=" SIZE_FORMAT_W(10) " max_ratio=%14.12f",
max_reclaimed_ratio_region, max_dead_to_right, max_live_to_right, max_reclaimed_ratio);
log_develop_trace(gc, compaction)("max: " SIZE_FORMAT_W(4) " d2r=" SIZE_FORMAT_W(10) " l2r=" SIZE_FORMAT_W(10) " max_ratio=%14.12f",
max_reclaimed_ratio_region, max_dead_to_right, max_live_to_right, max_reclaimed_ratio);
}
void
print_initial_summary_data(ParallelCompactData& summary_data,
SpaceInfo* space_info) {
if (!log_develop_is_enabled(Trace, gc, compaction, phases)) {
if (!log_develop_is_enabled(Trace, gc, compaction)) {
return;
}
@ -621,7 +621,7 @@ ParallelCompactData::summarize_split_space(size_t src_region,
sr->partial_obj_size()));
const size_t end_idx = addr_to_region_idx(target_end);
log_develop_trace(gc, compaction, phases)("split: clearing source_region field in [" SIZE_FORMAT ", " SIZE_FORMAT ")", beg_idx, end_idx);
log_develop_trace(gc, compaction)("split: clearing source_region field in [" SIZE_FORMAT ", " SIZE_FORMAT ")", beg_idx, end_idx);
for (size_t idx = beg_idx; idx < end_idx; ++idx) {
_region_data[idx].set_source_region(0);
}
@ -641,22 +641,22 @@ ParallelCompactData::summarize_split_space(size_t src_region,
*target_next = split_destination + partial_obj_size;
HeapWord* const source_next = region_to_addr(split_region) + partial_obj_size;
if (log_develop_is_enabled(Trace, gc, compaction, phases)) {
if (log_develop_is_enabled(Trace, gc, compaction)) {
const char * split_type = partial_obj_size == 0 ? "easy" : "hard";
log_develop_trace(gc, compaction, phases)("%s split: src=" PTR_FORMAT " src_c=" SIZE_FORMAT " pos=" SIZE_FORMAT,
split_type, p2i(source_next), split_region, partial_obj_size);
log_develop_trace(gc, compaction, phases)("%s split: dst=" PTR_FORMAT " dst_c=" SIZE_FORMAT " tn=" PTR_FORMAT,
split_type, p2i(split_destination),
addr_to_region_idx(split_destination),
p2i(*target_next));
log_develop_trace(gc, compaction)("%s split: src=" PTR_FORMAT " src_c=" SIZE_FORMAT " pos=" SIZE_FORMAT,
split_type, p2i(source_next), split_region, partial_obj_size);
log_develop_trace(gc, compaction)("%s split: dst=" PTR_FORMAT " dst_c=" SIZE_FORMAT " tn=" PTR_FORMAT,
split_type, p2i(split_destination),
addr_to_region_idx(split_destination),
p2i(*target_next));
if (partial_obj_size != 0) {
HeapWord* const po_beg = split_info.destination();
HeapWord* const po_end = po_beg + split_info.partial_obj_size();
log_develop_trace(gc, compaction, phases)("%s split: po_beg=" PTR_FORMAT " " SIZE_FORMAT " po_end=" PTR_FORMAT " " SIZE_FORMAT,
split_type,
p2i(po_beg), addr_to_region_idx(po_beg),
p2i(po_end), addr_to_region_idx(po_end));
log_develop_trace(gc, compaction)("%s split: po_beg=" PTR_FORMAT " " SIZE_FORMAT " po_end=" PTR_FORMAT " " SIZE_FORMAT,
split_type,
p2i(po_beg), addr_to_region_idx(po_beg),
p2i(po_end), addr_to_region_idx(po_end));
}
}
@ -670,7 +670,7 @@ bool ParallelCompactData::summarize(SplitInfo& split_info,
HeapWord** target_next)
{
HeapWord* const source_next_val = source_next == NULL ? NULL : *source_next;
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
"sb=" PTR_FORMAT " se=" PTR_FORMAT " sn=" PTR_FORMAT
"tb=" PTR_FORMAT " te=" PTR_FORMAT " tn=" PTR_FORMAT,
p2i(source_beg), p2i(source_end), p2i(source_next_val),
@ -938,7 +938,7 @@ void PSParallelCompact::pre_compact()
// at each young gen gc. Do the update unconditionally (even though a
// promotion failure does not swap spaces) because an unknown number of young
// collections will have swapped the spaces an unknown number of times.
GCTraceTime(Trace, gc, phases) tm("Pre Compact", &_gc_timer);
GCTraceTime(Debug, gc, phases) tm("Pre Compact", &_gc_timer);
ParallelScavengeHeap* heap = ParallelScavengeHeap::heap();
_space_info[from_space_id].set_space(heap->young_gen()->from_space());
_space_info[to_space_id].set_space(heap->young_gen()->to_space());
@ -981,7 +981,7 @@ void PSParallelCompact::pre_compact()
void PSParallelCompact::post_compact()
{
GCTraceTime(Trace, gc, phases) tm("Post Compact", &_gc_timer);
GCTraceTime(Info, gc, phases) tm("Post Compact", &_gc_timer);
for (unsigned int id = old_space_id; id < last_space_id; ++id) {
// Clear the marking bitmap, summary data and split info.
@ -1524,7 +1524,7 @@ PSParallelCompact::summarize_space(SpaceId id, bool maximum_compaction)
}
}
if (log_develop_is_enabled(Trace, gc, compaction, phases)) {
if (log_develop_is_enabled(Trace, gc, compaction)) {
const size_t region_size = ParallelCompactData::RegionSize;
HeapWord* const dense_prefix_end = _space_info[id].dense_prefix();
const size_t dp_region = _summary_data.addr_to_region_idx(dense_prefix_end);
@ -1532,7 +1532,7 @@ PSParallelCompact::summarize_space(SpaceId id, bool maximum_compaction)
HeapWord* const new_top = _space_info[id].new_top();
const HeapWord* nt_aligned_up = _summary_data.region_align_up(new_top);
const size_t cr_words = pointer_delta(nt_aligned_up, dense_prefix_end);
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
"id=%d cap=" SIZE_FORMAT " dp=" PTR_FORMAT " "
"dp_region=" SIZE_FORMAT " " "dp_count=" SIZE_FORMAT " "
"cr_count=" SIZE_FORMAT " " "nt=" PTR_FORMAT,
@ -1548,7 +1548,7 @@ void PSParallelCompact::summary_phase_msg(SpaceId dst_space_id,
SpaceId src_space_id,
HeapWord* src_beg, HeapWord* src_end)
{
log_develop_trace(gc, compaction, phases)(
log_develop_trace(gc, compaction)(
"Summarizing %d [%s] into %d [%s]: "
"src=" PTR_FORMAT "-" PTR_FORMAT " "
SIZE_FORMAT "-" SIZE_FORMAT " "
@ -1568,7 +1568,7 @@ void PSParallelCompact::summary_phase_msg(SpaceId dst_space_id,
void PSParallelCompact::summary_phase(ParCompactionManager* cm,
bool maximum_compaction)
{
GCTraceTime(Trace, gc, phases) tm("Summary Phase", &_gc_timer);
GCTraceTime(Info, gc, phases) tm("Summary Phase", &_gc_timer);
#ifdef ASSERT
if (TraceParallelOldGCMarkingPhase) {
@ -1584,7 +1584,7 @@ void PSParallelCompact::summary_phase(ParCompactionManager* cm,
// Quick summarization of each space into itself, to see how much is live.
summarize_spaces_quick();
log_develop_trace(gc, compaction, phases)("summary phase: after summarizing each space to self");
log_develop_trace(gc, compaction)("summary phase: after summarizing each space to self");
NOT_PRODUCT(print_region_ranges());
NOT_PRODUCT(print_initial_summary_data(_summary_data, _space_info));
@ -1660,7 +1660,7 @@ void PSParallelCompact::summary_phase(ParCompactionManager* cm,
}
}
log_develop_trace(gc, compaction, phases)("Summary_phase: after final summarization");
log_develop_trace(gc, compaction)("Summary_phase: after final summarization");
NOT_PRODUCT(print_region_ranges());
NOT_PRODUCT(print_initial_summary_data(_summary_data, _space_info));
}
@ -2042,7 +2042,7 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm,
bool maximum_heap_compaction,
ParallelOldTracer *gc_tracer) {
// Recursively traverse all live objects and mark them
GCTraceTime(Trace, gc, phases) tm("Marking Phase", &_gc_timer);
GCTraceTime(Info, gc, phases) tm("Marking Phase", &_gc_timer);
ParallelScavengeHeap* heap = ParallelScavengeHeap::heap();
uint parallel_gc_threads = heap->gc_task_manager()->workers();
@ -2057,7 +2057,7 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm,
ClassLoaderDataGraph::clear_claimed_marks();
{
GCTraceTime(Trace, gc, phases) tm("Par Mark", &_gc_timer);
GCTraceTime(Debug, gc, phases) tm("Par Mark", &_gc_timer);
ParallelScavengeHeap::ParStrongRootsScope psrs;
@ -2086,7 +2086,7 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm,
// Process reference objects found during marking
{
GCTraceTime(Trace, gc, phases) tm("Reference Processing", &_gc_timer);
GCTraceTime(Debug, gc, phases) tm("Reference Processing", &_gc_timer);
ReferenceProcessorStats stats;
if (ref_processor()->processing_is_mt()) {
@ -2107,7 +2107,7 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm,
assert(cm->marking_stacks_empty(), "Marking should have completed");
{
GCTraceTime(Debug, gc) tm_m("Class Unloading", &_gc_timer);
GCTraceTime(Debug, gc, phases) tm_m("Class Unloading", &_gc_timer);
// Follow system dictionary roots and unload classes.
bool purged_class = SystemDictionary::do_unloading(is_alive_closure());
@ -2120,13 +2120,13 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm,
}
{
GCTraceTime(Debug, gc) t("Scrub String Table", &_gc_timer);
GCTraceTime(Debug, gc, phases) t("Scrub String Table", &_gc_timer);
// Delete entries for dead interned strings.
StringTable::unlink(is_alive_closure());
}
{
GCTraceTime(Debug, gc) t("Scrub Symbol Table", &_gc_timer);
GCTraceTime(Debug, gc, phases) t("Scrub Symbol Table", &_gc_timer);
// Clean up unreferenced symbols in symbol table.
SymbolTable::unlink();
}
@ -2136,7 +2136,7 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm,
void PSParallelCompact::adjust_roots(ParCompactionManager* cm) {
// Adjust the pointers to reflect the new locations
GCTraceTime(Trace, gc, phases) tm("Adjust Roots", &_gc_timer);
GCTraceTime(Info, gc, phases) tm("Adjust Roots", &_gc_timer);
// Need new claim bits when tracing through and adjusting pointers.
ClassLoaderDataGraph::clear_claimed_marks();
@ -2410,7 +2410,7 @@ void PSParallelCompact::write_block_fill_histogram()
#endif // #ifdef ASSERT
void PSParallelCompact::compact() {
GCTraceTime(Trace, gc, phases) tm("Compaction Phase", &_gc_timer);
GCTraceTime(Info, gc, phases) tm("Compaction Phase", &_gc_timer);
ParallelScavengeHeap* heap = ParallelScavengeHeap::heap();
PSOldGen* old_gen = heap->old_gen();