< prev index next >
src/share/vm/gc/parallel/psParallelCompact.cpp
Print this page
@@ -47,10 +47,11 @@
#include "gc/shared/gcTraceTime.hpp"
#include "gc/shared/isGCActiveMark.hpp"
#include "gc/shared/referencePolicy.hpp"
#include "gc/shared/referenceProcessor.hpp"
#include "gc/shared/spaceDecorator.hpp"
+#include "logging/log.hpp"
#include "oops/instanceKlass.inline.hpp"
#include "oops/instanceMirrorKlass.inline.hpp"
#include "oops/methodData.hpp"
#include "oops/objArrayKlass.inline.hpp"
#include "oops/oop.inline.hpp"
@@ -104,11 +105,10 @@
const ParallelCompactData::RegionData::region_sz_t
ParallelCompactData::RegionData::dc_completed = 0xcU << dc_shift;
SpaceInfo PSParallelCompact::_space_info[PSParallelCompact::last_space_id];
-bool PSParallelCompact::_print_phases = false;
ReferenceProcessor* PSParallelCompact::_ref_processor = NULL;
double PSParallelCompact::_dwl_mean;
double PSParallelCompact::_dwl_std_dev;
@@ -191,18 +191,23 @@
#ifndef PRODUCT
const char* PSParallelCompact::space_names[] = {
"old ", "eden", "from", "to "
};
-void PSParallelCompact::print_region_ranges()
-{
- tty->print_cr("space bottom top end new_top");
- tty->print_cr("------ ---------- ---------- ---------- ----------");
+void PSParallelCompact::print_region_ranges() {
+ LogHandle(gc, compaction, phases) log;
+ if (!log.is_develop()) {
+ return;
+ }
+ ResourceMark rm;
+ Universe::print_on(log.develop_stream());
+ log.develop("space bottom top end new_top");
+ log.develop("------ ---------- ---------- ---------- ----------");
for (unsigned int id = 0; id < last_space_id; ++id) {
const MutableSpace* space = _space_info[id].space();
- tty->print_cr("%u %s "
+ log.develop("%u %s "
SIZE_FORMAT_W(10) " " SIZE_FORMAT_W(10) " "
SIZE_FORMAT_W(10) " " SIZE_FORMAT_W(10) " ",
id, space_names[id],
summary_data().addr_to_region_idx(space->bottom()),
summary_data().addr_to_region_idx(space->top()),
@@ -217,11 +222,12 @@
#define REGION_IDX_FORMAT SIZE_FORMAT_W(7)
#define REGION_DATA_FORMAT SIZE_FORMAT_W(5)
ParallelCompactData& sd = PSParallelCompact::summary_data();
size_t dci = c->destination() ? sd.addr_to_region_idx(c->destination()) : 0;
- tty->print_cr(REGION_IDX_FORMAT " " PTR_FORMAT " "
+ log_develop(gc, compaction, phases)(
+ REGION_IDX_FORMAT " " PTR_FORMAT " "
REGION_IDX_FORMAT " " PTR_FORMAT " "
REGION_DATA_FORMAT " " REGION_DATA_FORMAT " "
REGION_DATA_FORMAT " " REGION_IDX_FORMAT " %d",
i, p2i(c->data_location()), dci, p2i(c->destination()),
c->partial_obj_size(), c->live_obj_size(),
@@ -249,39 +255,29 @@
pdest = c->destination();
}
++i;
}
- tty->print_cr("summary_data_bytes=" SIZE_FORMAT, total_words * HeapWordSize);
+ log_develop(gc, compaction, phases)("summary_data_bytes=" SIZE_FORMAT, total_words * HeapWordSize);
}
void
print_generic_summary_data(ParallelCompactData& summary_data,
SpaceInfo* space_info)
{
+ if (!log_is_enabled(Develop, gc, compaction, phases)) {
+ return;
+ }
+
for (unsigned int id = 0; id < PSParallelCompact::last_space_id; ++id) {
const MutableSpace* space = space_info[id].space();
print_generic_summary_data(summary_data, space->bottom(),
MAX2(space->top(), space_info[id].new_top()));
}
}
void
-print_initial_summary_region(size_t i,
- const ParallelCompactData::RegionData* c,
- bool newline = true)
-{
- tty->print(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());
- if (newline) tty->cr();
-}
-
-void
print_initial_summary_data(ParallelCompactData& summary_data,
const MutableSpace* space) {
if (space->top() == space->bottom()) {
return;
}
@@ -296,11 +292,16 @@
// Print (and count) the full regions at the beginning of the space.
size_t full_region_count = 0;
size_t i = summary_data.addr_to_region_idx(space->bottom());
while (i < end_region && summary_data.region(i)->data_size() == region_size) {
- print_initial_summary_region(i, summary_data.region(i));
+ ParallelCompactData::RegionData* c = summary_data.region(i);
+ log_develop(gc, compaction, phases)(
+ 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());
++full_region_count;
++i;
}
size_t live_to_right = live_in_space - full_region_count * region_size;
@@ -325,32 +326,45 @@
max_reclaimed_ratio_region = i;
max_dead_to_right = dead_to_right;
max_live_to_right = live_to_right;
}
- print_initial_summary_region(i, c, false);
- tty->print_cr(" %12.10f " SIZE_FORMAT_W(10) " " SIZE_FORMAT_W(10),
+ ParallelCompactData::RegionData* c = summary_data.region(i);
+ log_develop(gc, compaction, phases)(
+ 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()),
+ c->partial_obj_size(), c->live_obj_size(),
+ c->data_size(), c->source_region(), c->destination_count(),
reclaimed_ratio, dead_to_right, live_to_right);
+
live_to_right -= c->data_size();
++i;
}
// Any remaining regions are empty. Print one more if there is one.
if (i < end_region) {
- print_initial_summary_region(i, summary_data.region(i));
+ ParallelCompactData::RegionData* c = summary_data.region(i);
+ log_develop(gc, compaction, phases)(
+ 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());
}
- tty->print_cr("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(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);
}
void
print_initial_summary_data(ParallelCompactData& summary_data,
SpaceInfo* space_info) {
+ if (!log_is_enabled(Develop, gc, compaction, phases)) {
+ return;
+ }
+
unsigned int id = PSParallelCompact::old_space_id;
const MutableSpace* space;
do {
space = space_info[id].space();
print_initial_summary_data(summary_data, space);
@@ -604,15 +618,11 @@
const size_t beg_idx =
addr_to_region_idx(region_align_up(sr->destination() +
sr->partial_obj_size()));
const size_t end_idx = addr_to_region_idx(target_end);
- if (TraceParallelOldGCSummaryPhase) {
- gclog_or_tty->print_cr("split: clearing source_region field in ["
- SIZE_FORMAT ", " SIZE_FORMAT ")",
- beg_idx, end_idx);
- }
+ log_develop(gc, compaction, phases)("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);
}
// Set split_destination and partial_obj_size to reflect the split region.
@@ -628,28 +638,23 @@
// Setup the continuation addresses.
*target_next = split_destination + partial_obj_size;
HeapWord* const source_next = region_to_addr(split_region) + partial_obj_size;
- if (TraceParallelOldGCSummaryPhase) {
+ if (log_is_enabled(Develop, gc, compaction, phases)) {
const char * split_type = partial_obj_size == 0 ? "easy" : "hard";
- gclog_or_tty->print_cr("%s split: src=" PTR_FORMAT " src_c=" SIZE_FORMAT
- " pos=" SIZE_FORMAT,
- split_type, p2i(source_next), split_region,
- partial_obj_size);
- gclog_or_tty->print_cr("%s split: dst=" PTR_FORMAT " dst_c=" SIZE_FORMAT
- " tn=" PTR_FORMAT,
+ log_develop(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(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));
if (partial_obj_size != 0) {
HeapWord* const po_beg = split_info.destination();
HeapWord* const po_end = po_beg + split_info.partial_obj_size();
- gclog_or_tty->print_cr("%s split: "
- "po_beg=" PTR_FORMAT " " SIZE_FORMAT " "
- "po_end=" PTR_FORMAT " " SIZE_FORMAT,
+ log_develop(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));
}
}
@@ -661,17 +666,16 @@
HeapWord* source_beg, HeapWord* source_end,
HeapWord** source_next,
HeapWord* target_beg, HeapWord* target_end,
HeapWord** target_next)
{
- if (TraceParallelOldGCSummaryPhase) {
HeapWord* const source_next_val = source_next == NULL ? NULL : *source_next;
- tty->print_cr("sb=" PTR_FORMAT " se=" PTR_FORMAT " sn=" PTR_FORMAT
+ log_develop(gc, compaction, phases)(
+ "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),
p2i(target_beg), p2i(target_end), p2i(*target_next));
- }
size_t cur_region = addr_to_region_idx(source_beg);
const size_t end_region = addr_to_region_idx(region_align_up(source_end));
HeapWord *dest_addr = target_beg;
@@ -898,36 +902,10 @@
_dwl_first_term = 1.0 / (sqrt(2.0 * M_PI) * _dwl_std_dev);
DEBUG_ONLY(_dwl_initialized = true;)
_dwl_adjustment = normal_distribution(1.0);
}
-// Simple class for storing info about the heap at the start of GC, to be used
-// after GC for comparison/printing.
-class PreGCValues {
-public:
- PreGCValues() { }
- PreGCValues(ParallelScavengeHeap* heap) { fill(heap); }
-
- void fill(ParallelScavengeHeap* heap) {
- _heap_used = heap->used();
- _young_gen_used = heap->young_gen()->used_in_bytes();
- _old_gen_used = heap->old_gen()->used_in_bytes();
- _metadata_used = MetaspaceAux::used_bytes();
- };
-
- size_t heap_used() const { return _heap_used; }
- size_t young_gen_used() const { return _young_gen_used; }
- size_t old_gen_used() const { return _old_gen_used; }
- size_t metadata_used() const { return _metadata_used; }
-
-private:
- size_t _heap_used;
- size_t _young_gen_used;
- size_t _old_gen_used;
- size_t _metadata_used;
-};
-
void
PSParallelCompact::clear_data_covering_space(SpaceId id)
{
// At this point, top is the value before GC, new_top() is the value that will
// be set at the end of GC. The marking bitmap is cleared to top; nothing
@@ -953,23 +931,21 @@
split_info.clear();
}
DEBUG_ONLY(split_info.verify_clear();)
}
-void PSParallelCompact::pre_compact(PreGCValues* pre_gc_values)
+void PSParallelCompact::pre_compact()
{
// Update the from & to space pointers in space_info, since they are swapped
// 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 tm("pre compact", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, 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());
- pre_gc_values->fill(heap);
-
DEBUG_ONLY(add_obj_count = add_obj_size = 0;)
DEBUG_ONLY(mark_bitmap_count = mark_bitmap_size = 0;)
// Increment the invocation count
heap->increment_total_collections(true);
@@ -984,11 +960,11 @@
heap->accumulate_statistics_all_tlabs();
heap->ensure_parsability(true); // retire TLABs
if (VerifyBeforeGC && heap->total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
- Universe::verify(" VerifyBeforeGC:");
+ Universe::verify("Before GC");
}
// Verify object start arrays
if (VerifyObjectStartArray &&
VerifyBeforeGC) {
@@ -1002,11 +978,11 @@
gc_task_manager()->release_all_resources();
}
void PSParallelCompact::post_compact()
{
- GCTraceTime tm("post compact", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, 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.
clear_data_covering_space(SpaceId(id));
// Update top(). Must be done after clearing the bitmap and summary data.
@@ -1556,19 +1532,20 @@
dense_prefix_end, space->end(),
_space_info[id].new_top_addr());
}
}
- if (TraceParallelOldGCSummaryPhase) {
+ if (log_is_enabled(Develop, gc, compaction, phases)) {
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);
const size_t dp_words = pointer_delta(dense_prefix_end, space->bottom());
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);
- tty->print_cr("id=%d cap=" SIZE_FORMAT " dp=" PTR_FORMAT " "
+ log_develop(gc, compaction, phases)(
+ "id=%d cap=" SIZE_FORMAT " dp=" PTR_FORMAT " "
"dp_region=" SIZE_FORMAT " " "dp_count=" SIZE_FORMAT " "
"cr_count=" SIZE_FORMAT " " "nt=" PTR_FORMAT,
id, space->capacity_in_words(), p2i(dense_prefix_end),
dp_region, dp_words / region_size,
cr_words / region_size, p2i(new_top));
@@ -1579,12 +1556,12 @@
void PSParallelCompact::summary_phase_msg(SpaceId dst_space_id,
HeapWord* dst_beg, HeapWord* dst_end,
SpaceId src_space_id,
HeapWord* src_beg, HeapWord* src_end)
{
- if (TraceParallelOldGCSummaryPhase) {
- tty->print_cr("summarizing %d [%s] into %d [%s]: "
+ log_develop(gc, compaction, phases)(
+ "Summarizing %d [%s] into %d [%s]: "
"src=" PTR_FORMAT "-" PTR_FORMAT " "
SIZE_FORMAT "-" SIZE_FORMAT " "
"dst=" PTR_FORMAT "-" PTR_FORMAT " "
SIZE_FORMAT "-" SIZE_FORMAT,
src_space_id, space_names[src_space_id],
@@ -1593,19 +1570,17 @@
_summary_data.addr_to_region_idx(src_beg),
_summary_data.addr_to_region_idx(src_end),
p2i(dst_beg), p2i(dst_end),
_summary_data.addr_to_region_idx(dst_beg),
_summary_data.addr_to_region_idx(dst_end));
- }
}
#endif // #ifndef PRODUCT
void PSParallelCompact::summary_phase(ParCompactionManager* cm,
bool maximum_compaction)
{
- GCTraceTime tm("summary phase", print_phases(), true, &_gc_timer);
- // trace("2");
+ GCTraceTime(Trace, gc, phases) tm("summary phase", &_gc_timer);
#ifdef ASSERT
if (TraceParallelOldGCMarkingPhase) {
tty->print_cr("add_obj_count=" SIZE_FORMAT " "
"add_obj_bytes=" SIZE_FORMAT,
@@ -1617,18 +1592,13 @@
#endif // #ifdef ASSERT
// Quick summarization of each space into itself, to see how much is live.
summarize_spaces_quick();
- if (TraceParallelOldGCSummaryPhase) {
- tty->print_cr("summary_phase: after summarizing each space to self");
- Universe::print();
+ log_develop(gc, compaction, phases)("Summary_phase: after summarizing each space to self");
NOT_PRODUCT(print_region_ranges());
- if (Verbose) {
NOT_PRODUCT(print_initial_summary_data(_summary_data, _space_info));
- }
- }
// The amount of live data that will end up in old space (assuming it fits).
size_t old_space_total_live = 0;
for (unsigned int id = old_space_id; id < last_space_id; ++id) {
old_space_total_live += pointer_delta(_space_info[id].new_top(),
@@ -1698,18 +1668,13 @@
assert(done, "space must fit when compacted into itself");
assert(*new_top_addr <= space->top(), "usage should not grow");
}
}
- if (TraceParallelOldGCSummaryPhase) {
- tty->print_cr("summary_phase: after final summarization");
- Universe::print();
+ log_develop(gc, compaction, phases)("Summary_phase: after final summarization");
NOT_PRODUCT(print_region_ranges());
- if (Verbose) {
- NOT_PRODUCT(print_generic_summary_data(_summary_data, _space_info));
- }
- }
+ NOT_PRODUCT(print_initial_summary_data(_summary_data, _space_info));
}
// This method should contain all heap-specific policy for invoking a full
// collection. invoke_no_policy() will only attempt to compact the heap; it
// will do nothing further. If we need to bail out for policy reasons, scavenge
@@ -1780,34 +1745,30 @@
heap->record_gen_tops_before_GC();
}
heap->pre_full_gc_dump(&_gc_timer);
- _print_phases = PrintGCDetails && PrintParallelOldGCPhaseTimes;
-
// Make sure data structures are sane, make the heap parsable, and do other
// miscellaneous bookkeeping.
- PreGCValues pre_gc_values;
- pre_compact(&pre_gc_values);
+ pre_compact();
+
+ PreGCValues pre_gc_values(heap);
// Get the compaction manager reserved for the VM thread.
ParCompactionManager* const vmthread_cm =
ParCompactionManager::manager_array(gc_task_manager()->workers());
- // Place after pre_compact() where the number of invocations is incremented.
- AdaptiveSizePolicyOutput(size_policy, heap->total_collections());
-
{
ResourceMark rm;
HandleMark hm;
// Set the number of GC threads to be used in this collection
gc_task_manager()->set_active_gang();
gc_task_manager()->task_idle_workers();
- TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
- GCTraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, NULL);
+ GCTraceCPUTime tcpu;
+ GCTraceTime(Info, gc) tm("Pause Full", NULL, gc_cause, true);
TraceCollectorStats tcs(counters());
TraceMemoryManagerStats tms(true /* Full GC */,gc_cause);
if (TraceOldGenTime) accumulated_time()->start();
@@ -1850,21 +1811,13 @@
// Let the size policy know we're done
size_policy->major_collection_end(old_gen->used_in_bytes(), gc_cause);
if (UseAdaptiveSizePolicy) {
- if (PrintAdaptiveSizePolicy) {
- gclog_or_tty->print("AdaptiveSizeStart: ");
- gclog_or_tty->stamp();
- gclog_or_tty->print_cr(" collection: %d ",
- heap->total_collections());
- if (Verbose) {
- gclog_or_tty->print("old_gen_capacity: " SIZE_FORMAT
- " young_gen_capacity: " SIZE_FORMAT,
+ log_debug(gc, ergo)("AdaptiveSizeStart: collection: %d ", heap->total_collections());
+ log_trace(gc, ergo)("old_gen_capacity: " SIZE_FORMAT " young_gen_capacity: " SIZE_FORMAT,
old_gen->capacity_in_bytes(), young_gen->capacity_in_bytes());
- }
- }
// Don't check if the size_policy is ready here. Let
// the size_policy check that internally.
if (UseAdaptiveGenerationSizePolicyAtMajorCollection &&
AdaptiveSizePolicy::should_update_promo_stats(gc_cause)) {
@@ -1918,14 +1871,12 @@
size_policy->calculated_old_free_size_in_bytes());
heap->resize_young_gen(size_policy->calculated_eden_size_in_bytes(),
size_policy->calculated_survivor_size_in_bytes());
}
- if (PrintAdaptiveSizePolicy) {
- gclog_or_tty->print_cr("AdaptiveSizeStop: collection: %d ",
- heap->total_collections());
- }
+
+ log_debug(gc, ergo)("AdaptiveSizeStop: collection: %d ", heap->total_collections());
}
if (UsePerfData) {
PSGCAdaptivePolicyCounters* const counters = heap->gc_policy_counters();
counters->update_counters();
@@ -1936,23 +1887,17 @@
heap->resize_all_tlabs();
// Resize the metaspace capacity after a collection
MetaspaceGC::compute_new_size();
- if (TraceOldGenTime) accumulated_time()->stop();
+ if (TraceOldGenTime) {
+ accumulated_time()->stop();
+ }
- if (PrintGC) {
- if (PrintGCDetails) {
- // No GC timestamp here. This is after GC so it would be confusing.
young_gen->print_used_change(pre_gc_values.young_gen_used());
old_gen->print_used_change(pre_gc_values.old_gen_used());
- heap->print_heap_change(pre_gc_values.heap_used());
MetaspaceAux::print_metaspace_change(pre_gc_values.metadata_used());
- } else {
- heap->print_heap_change(pre_gc_values.heap_used());
- }
- }
// Track memory usage and detect low memory
MemoryService::track_memory_usage();
heap->update_counters();
gc_task_manager()->release_idle_workers();
@@ -1967,11 +1912,11 @@
}
#endif // ASSERT
if (VerifyAfterGC && heap->total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
- Universe::verify(" VerifyAfterGC:");
+ Universe::verify("After GC");
}
// Re-verify object start arrays
if (VerifyObjectStartArray &&
VerifyAfterGC) {
@@ -1987,24 +1932,23 @@
collection_exit.update();
heap->print_heap_after_gc();
heap->trace_heap_after_gc(&_gc_tracer);
- if (PrintGCTaskTimeStamps) {
- gclog_or_tty->print_cr("VM-Thread " JLONG_FORMAT " " JLONG_FORMAT " "
- JLONG_FORMAT,
+ log_debug(gc, task, time)("VM-Thread " JLONG_FORMAT " " JLONG_FORMAT " " JLONG_FORMAT,
marking_start.ticks(), compaction_start.ticks(),
collection_exit.ticks());
gc_task_manager()->print_task_time_stamps();
- }
heap->post_full_gc_dump(&_gc_timer);
#ifdef TRACESPINNING
ParallelTaskTerminator::print_termination_counts();
#endif
+ AdaptiveSizePolicyOutput::print(size_policy, heap->total_collections());
+
_gc_timer.register_gc_end();
_gc_tracer.report_dense_prefix(dense_prefix(old_space_id));
_gc_tracer.report_gc_end(_gc_timer.gc_end(), _gc_timer.time_partitions());
@@ -2047,21 +1991,19 @@
const size_t new_young_size = young_gen->capacity_in_bytes() - absorb_size;
if (new_young_size < young_gen->min_gen_size()) {
return false; // Respect young gen minimum size.
}
- if (TraceAdaptiveGCBoundary && Verbose) {
- gclog_or_tty->print(" absorbing " SIZE_FORMAT "K: "
+ log_trace(heap, ergo)(" absorbing " SIZE_FORMAT "K: "
"eden " SIZE_FORMAT "K->" SIZE_FORMAT "K "
"from " SIZE_FORMAT "K, to " SIZE_FORMAT "K "
"young_gen " SIZE_FORMAT "K->" SIZE_FORMAT "K ",
absorb_size / K,
eden_capacity / K, (eden_capacity - absorb_size) / K,
young_gen->from_space()->used_in_bytes() / K,
young_gen->to_space()->used_in_bytes() / K,
young_gen->capacity_in_bytes() / K, new_young_size / K);
- }
// Fill the unused part of the old gen.
MutableSpace* const old_space = old_gen->object_space();
HeapWord* const unused_start = old_space->top();
size_t const unused_words = pointer_delta(old_space->end(), unused_start);
@@ -2107,11 +2049,11 @@
void PSParallelCompact::marking_phase(ParCompactionManager* cm,
bool maximum_heap_compaction,
ParallelOldTracer *gc_tracer) {
// Recursively traverse all live objects and mark them
- GCTraceTime tm("marking phase", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("marking phase", &_gc_timer);
ParallelScavengeHeap* heap = ParallelScavengeHeap::heap();
uint parallel_gc_threads = heap->gc_task_manager()->workers();
uint active_gc_threads = heap->gc_task_manager()->active_workers();
TaskQueueSetSuper* qset = ParCompactionManager::region_array();
@@ -2122,11 +2064,11 @@
// Need new claim bits before marking starts.
ClassLoaderDataGraph::clear_claimed_marks();
{
- GCTraceTime tm_m("par mark", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("par mark", &_gc_timer);
ParallelScavengeHeap::ParStrongRootsScope psrs;
GCTaskQueue* q = GCTaskQueue::create();
@@ -2151,11 +2093,11 @@
gc_task_manager()->execute_and_wait(q);
}
// Process reference objects found during marking
{
- GCTraceTime tm_r("reference processing", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("reference processing", &_gc_timer);
ReferenceProcessorStats stats;
if (ref_processor()->processing_is_mt()) {
RefProcTaskExecutor task_executor;
stats = ref_processor()->process_discovered_references(
@@ -2168,11 +2110,11 @@
}
gc_tracer->report_gc_reference_stats(stats);
}
- GCTraceTime tm_c("class unloading", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc) tm_m("class unloading", &_gc_timer);
// This is the point where the entire marking should have completed.
assert(cm->marking_stacks_empty(), "Marking should have completed");
// Follow system dictionary roots and unload classes.
@@ -2199,11 +2141,11 @@
};
static PSAlwaysTrueClosure always_true;
void PSParallelCompact::adjust_roots() {
// Adjust the pointers to reflect the new locations
- GCTraceTime tm("adjust roots", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("adjust roots", &_gc_timer);
// Need new claim bits when tracing through and adjusting pointers.
ClassLoaderDataGraph::clear_claimed_marks();
// General strong roots.
@@ -2232,14 +2174,53 @@
// Should the reference processor have a span that excludes
// young gen objects?
PSScavenge::reference_processor()->weak_oops_do(adjust_pointer_closure());
}
+// Helper class to print 8 region numbers per line and then print the total at the end.
+class FillableRegionLogger : public StackObj {
+private:
+ LogHandle(gc, compaction) log;
+ static const int LineLength = 8;
+ size_t _regions[LineLength];
+ int _next_index;
+ bool _enabled;
+ size_t _total_regions;
+public:
+ FillableRegionLogger() : _next_index(0), _total_regions(0), _enabled(log.is_develop()) { }
+ ~FillableRegionLogger() {
+ log.develop(SIZE_FORMAT " initially fillable regions", _total_regions);
+ }
+
+ void print_line() {
+ if (!_enabled || _next_index == 0) {
+ return;
+ }
+ FormatBuffer<> line("Fillable: ");
+ for (int i = 0; i < _next_index; i++) {
+ line.append(" " SIZE_FORMAT_W(7), _regions[i]);
+ }
+ log.develop("%s", line.buffer());
+ _next_index = 0;
+ }
+
+ void handle(size_t region) {
+ if (!_enabled) {
+ return;
+ }
+ _regions[_next_index++] = region;
+ if (_next_index == LineLength) {
+ print_line();
+ }
+ _total_regions++;
+ }
+};
+
void PSParallelCompact::enqueue_region_draining_tasks(GCTaskQueue* q,
uint parallel_gc_threads)
{
- GCTraceTime tm("drain task setup", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("drain task setup", &_gc_timer);
// Find the threads that are active
unsigned int which = 0;
const uint task_count = MAX2(parallel_gc_threads, 1U);
@@ -2260,17 +2241,17 @@
// distribute them to the thread stacks. The iteration is done in reverse
// order (high to low) so the regions will be removed in ascending order.
const ParallelCompactData& sd = PSParallelCompact::summary_data();
- size_t fillable_regions = 0; // A count for diagnostic purposes.
// A region index which corresponds to the tasks created above.
// "which" must be 0 <= which < task_count
which = 0;
// id + 1 is used to test termination so unsigned can
// be used with an old_space_id == 0.
+ FillableRegionLogger region_logger;
for (unsigned int id = to_space_id; id + 1 > old_space_id; --id) {
SpaceInfo* const space_info = _space_info + id;
MutableSpace* const space = space_info->space();
HeapWord* const new_top = space_info->new_top();
@@ -2279,41 +2260,28 @@
sd.addr_to_region_idx(sd.region_align_up(new_top));
for (size_t cur = end_region - 1; cur + 1 > beg_region; --cur) {
if (sd.region(cur)->claim_unsafe()) {
ParCompactionManager::region_list_push(which, cur);
-
- if (TraceParallelOldGCCompactionPhase && Verbose) {
- const size_t count_mod_8 = fillable_regions & 7;
- if (count_mod_8 == 0) gclog_or_tty->print("fillable: ");
- gclog_or_tty->print(" " SIZE_FORMAT_W(7), cur);
- if (count_mod_8 == 7) gclog_or_tty->cr();
- }
-
- NOT_PRODUCT(++fillable_regions;)
-
+ region_logger.handle(cur);
// Assign regions to tasks in round-robin fashion.
if (++which == task_count) {
assert(which <= parallel_gc_threads,
"Inconsistent number of workers");
which = 0;
}
}
}
- }
-
- if (TraceParallelOldGCCompactionPhase) {
- if (Verbose && (fillable_regions & 7) != 0) gclog_or_tty->cr();
- gclog_or_tty->print_cr(SIZE_FORMAT " initially fillable regions", fillable_regions);
+ region_logger.print_line();
}
}
#define PAR_OLD_DENSE_PREFIX_OVER_PARTITIONING 4
void PSParallelCompact::enqueue_dense_prefix_tasks(GCTaskQueue* q,
uint parallel_gc_threads) {
- GCTraceTime tm("dense prefix task setup", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("dense prefix task setup", &_gc_timer);
ParallelCompactData& sd = PSParallelCompact::summary_data();
// Iterate over all the spaces adding tasks for updating
// regions in the dense prefix. Assume that 1 gc thread
@@ -2391,11 +2359,11 @@
void PSParallelCompact::enqueue_region_stealing_tasks(
GCTaskQueue* q,
ParallelTaskTerminator* terminator_ptr,
uint parallel_gc_threads) {
- GCTraceTime tm("steal task setup", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("steal task setup", &_gc_timer);
// Once a thread has drained it's stack, it should try to steal regions from
// other threads.
if (parallel_gc_threads > 1) {
for (uint j = 0; j < parallel_gc_threads; j++) {
@@ -2405,13 +2373,17 @@
}
#ifdef ASSERT
// Write a histogram of the number of times the block table was filled for a
// region.
-void PSParallelCompact::write_block_fill_histogram(outputStream* const out)
+void PSParallelCompact::write_block_fill_histogram()
{
- if (!TraceParallelOldGCCompactionPhase) return;
+ LogHandle(gc, compaction) log;
+ if (!log.is_develop()) return;
+
+ ResourceMark rm;
+ outputStream* out = log.develop_stream();
typedef ParallelCompactData::RegionData rd_t;
ParallelCompactData& sd = summary_data();
for (unsigned int id = old_space_id; id < last_space_id; ++id) {
@@ -2426,11 +2398,11 @@
const size_t region_cnt = pointer_delta(end, beg, sizeof(rd_t));
for (const rd_t* cur = beg; cur < end; ++cur) {
++histo[MIN2(cur->blocks_filled_count(), histo_len - 1)];
}
- out->print("%u %-4s" SIZE_FORMAT_W(5), id, space_names[id], region_cnt);
+ out->print("Block fill histogram: %u %-4s" SIZE_FORMAT_W(5), id, space_names[id], region_cnt);
for (size_t i = 0; i < histo_len; ++i) {
out->print(" " SIZE_FORMAT_W(5) " %5.1f%%",
histo[i], 100.0 * histo[i] / region_cnt);
}
out->cr();
@@ -2438,12 +2410,11 @@
}
}
#endif // #ifdef ASSERT
void PSParallelCompact::compact() {
- // trace("5");
- GCTraceTime tm("compaction phase", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("compaction phase", &_gc_timer);
ParallelScavengeHeap* heap = ParallelScavengeHeap::heap();
PSOldGen* old_gen = heap->old_gen();
old_gen->start_array()->reset();
uint parallel_gc_threads = heap->gc_task_manager()->workers();
@@ -2455,11 +2426,11 @@
enqueue_region_draining_tasks(q, active_gc_threads);
enqueue_dense_prefix_tasks(q, active_gc_threads);
enqueue_region_stealing_tasks(q, &terminator, active_gc_threads);
{
- GCTraceTime tm_pc("par compact", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("par compact", &_gc_timer);
gc_task_manager()->execute_and_wait(q);
#ifdef ASSERT
// Verify that all regions have been processed before the deferred updates.
@@ -2469,18 +2440,18 @@
#endif
}
{
// Update the deferred objects, if any. Any compaction manager can be used.
- GCTraceTime tm_du("deferred updates", print_phases(), true, &_gc_timer);
+ GCTraceTime(Trace, gc, phases) tm("deferred updates", &_gc_timer);
ParCompactionManager* cm = ParCompactionManager::manager_array(0);
for (unsigned int id = old_space_id; id < last_space_id; ++id) {
update_deferred_objects(cm, SpaceId(id));
}
}
- DEBUG_ONLY(write_block_fill_histogram(gclog_or_tty));
+ DEBUG_ONLY(write_block_fill_histogram());
}
#ifdef ASSERT
void PSParallelCompact::verify_complete(SpaceId space_id) {
// All Regions between space bottom() to new_top() should be marked as filled
@@ -3105,22 +3076,17 @@
#ifdef ASSERT
template <class T> static void trace_reference_gc(const char *s, oop obj,
T* referent_addr,
T* next_addr,
T* discovered_addr) {
- if(TraceReferenceGC && PrintGCDetails) {
- gclog_or_tty->print_cr("%s obj " PTR_FORMAT, s, p2i(obj));
- gclog_or_tty->print_cr(" referent_addr/* " PTR_FORMAT " / "
- PTR_FORMAT, p2i(referent_addr),
- referent_addr ? p2i(oopDesc::load_decode_heap_oop(referent_addr)) : NULL);
- gclog_or_tty->print_cr(" next_addr/* " PTR_FORMAT " / "
- PTR_FORMAT, p2i(next_addr),
- next_addr ? p2i(oopDesc::load_decode_heap_oop(next_addr)) : NULL);
- gclog_or_tty->print_cr(" discovered_addr/* " PTR_FORMAT " / "
- PTR_FORMAT, p2i(discovered_addr),
- discovered_addr ? p2i(oopDesc::load_decode_heap_oop(discovered_addr)) : NULL);
- }
+ log_develop(gc, ref)("%s obj " PTR_FORMAT, s, p2i(obj));
+ log_develop(gc, ref)(" referent_addr/* " PTR_FORMAT " / " PTR_FORMAT,
+ p2i(referent_addr), referent_addr ? p2i(oopDesc::load_decode_heap_oop(referent_addr)) : NULL);
+ log_develop(gc, ref)(" next_addr/* " PTR_FORMAT " / " PTR_FORMAT,
+ p2i(next_addr), next_addr ? p2i(oopDesc::load_decode_heap_oop(next_addr)) : NULL);
+ log_develop(gc, ref)(" discovered_addr/* " PTR_FORMAT " / " PTR_FORMAT,
+ p2i(discovered_addr), discovered_addr ? p2i(oopDesc::load_decode_heap_oop(discovered_addr)) : NULL);
}
#endif
template <class T>
static void oop_pc_update_pointers_specialized(oop obj) {
< prev index next >