< prev index next >
src/share/vm/gc/g1/concurrentMark.cpp
Print this page
*** 29,40 ****
#include "gc/g1/concurrentMark.inline.hpp"
#include "gc/g1/concurrentMarkThread.inline.hpp"
#include "gc/g1/g1CollectedHeap.inline.hpp"
#include "gc/g1/g1CollectorPolicy.hpp"
#include "gc/g1/g1CollectorState.hpp"
- #include "gc/g1/g1ErgoVerbose.hpp"
- #include "gc/g1/g1Log.hpp"
#include "gc/g1/g1OopClosures.inline.hpp"
#include "gc/g1/g1RemSet.hpp"
#include "gc/g1/g1StringDedup.hpp"
#include "gc/g1/heapRegion.inline.hpp"
#include "gc/g1/heapRegionManager.inline.hpp"
--- 29,38 ----
*** 48,57 ****
--- 46,56 ----
#include "gc/shared/genOopClosures.inline.hpp"
#include "gc/shared/referencePolicy.hpp"
#include "gc/shared/strongRootsScope.hpp"
#include "gc/shared/taskqueue.inline.hpp"
#include "gc/shared/vmGCOperations.hpp"
+ #include "logging/log.hpp"
#include "memory/allocation.hpp"
#include "memory/resourceArea.hpp"
#include "oops/oop.inline.hpp"
#include "runtime/atomic.inline.hpp"
#include "runtime/handles.inline.hpp"
*** 277,289 ****
assert(isEmpty(), "stack should been emptied while handling overflow");
assert(_capacity <= (jint) MarkStackSizeMax, "stack bigger than permitted");
// Clear expansion flag
_should_expand = false;
if (_capacity == (jint) MarkStackSizeMax) {
! if (PrintGCDetails && Verbose) {
! gclog_or_tty->print_cr(" (benign) Can't expand marking stack capacity, at max size limit");
! }
return;
}
// Double capacity if possible
jint new_capacity = MIN2(_capacity*2, (jint) MarkStackSizeMax);
// Do not give up existing stack until we have managed to
--- 276,286 ----
assert(isEmpty(), "stack should been emptied while handling overflow");
assert(_capacity <= (jint) MarkStackSizeMax, "stack bigger than permitted");
// Clear expansion flag
_should_expand = false;
if (_capacity == (jint) MarkStackSizeMax) {
! log_trace(gc)("(benign) Can't expand marking stack capacity, at max size limit");
return;
}
// Double capacity if possible
jint new_capacity = MIN2(_capacity*2, (jint) MarkStackSizeMax);
// Do not give up existing stack until we have managed to
*** 299,315 ****
}
_base = (oop*)(_virtual_space.low());
_index = 0;
_capacity = new_capacity;
} else {
- if (PrintGCDetails && Verbose) {
// Failed to double capacity, continue;
! gclog_or_tty->print(" (benign) Failed to expand marking stack capacity from "
! SIZE_FORMAT "K to " SIZE_FORMAT "K",
_capacity / K, new_capacity / K);
}
- }
}
void CMMarkStack::set_should_expand() {
// If we're resetting the marking state because of an
// marking stack overflow, record that we should, if
--- 296,309 ----
}
_base = (oop*)(_virtual_space.low());
_index = 0;
_capacity = new_capacity;
} else {
// Failed to double capacity, continue;
! log_trace(gc)("(benign) Failed to expand marking stack capacity from " SIZE_FORMAT "K to " SIZE_FORMAT "K",
_capacity / K, new_capacity / K);
}
}
void CMMarkStack::set_should_expand() {
// If we're resetting the marking state because of an
// marking stack overflow, record that we should, if
*** 574,591 ****
_cleanup_task_overhead = marking_task_overhead();
}
_cleanup_sleep_factor =
(1.0 - cleanup_task_overhead()) / cleanup_task_overhead();
- #if 0
- gclog_or_tty->print_cr("Marking Threads %d", parallel_marking_threads());
- gclog_or_tty->print_cr("CM Marking Task Overhead %1.4lf", marking_task_overhead());
- gclog_or_tty->print_cr("CM Sleep Factor %1.4lf", sleep_factor());
- gclog_or_tty->print_cr("CL Marking Task Overhead %1.4lf", cleanup_task_overhead());
- gclog_or_tty->print_cr("CL Sleep Factor %1.4lf", cleanup_sleep_factor());
- #endif
-
_parallel_workers = new WorkGang("G1 Marker",
_max_parallel_marking_threads, false, true);
if (_parallel_workers == NULL) {
vm_exit_during_initialization("Failed necessary allocation.");
} else {
--- 568,577 ----
*** 920,933 ****
// we exit this method to abort the pause and restart concurrent
// marking.
reset_marking_state(true /* clear_overflow */);
force_overflow()->update();
! if (G1Log::fine()) {
! gclog_or_tty->gclog_stamp();
! gclog_or_tty->print_cr("[GC concurrent-mark-reset-for-overflow]");
! }
}
}
// after this, each task should reset its own data structures then
// then go into the second barrier
--- 906,916 ----
// we exit this method to abort the pause and restart concurrent
// marking.
reset_marking_state(true /* clear_overflow */);
force_overflow()->update();
! log_info(gc)("Concurrent Mark reset for overflow");
}
}
// after this, each task should reset its own data structures then
// then go into the second barrier
*** 1085,1121 ****
}
}
};
void ConcurrentMark::scanRootRegions() {
! double scan_start = os::elapsedTime();
// Start of concurrent marking.
ClassLoaderDataGraph::clear_claimed_marks();
// scan_in_progress() will have been set to true only if there was
// at least one root region to scan. So, if it's false, we
// should not attempt to do any further work.
if (root_regions()->scan_in_progress()) {
! if (G1Log::fine()) {
! gclog_or_tty->gclog_stamp();
! gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]");
! }
_parallel_marking_threads = calc_parallel_marking_threads();
assert(parallel_marking_threads() <= max_parallel_marking_threads(),
"Maximum number of marking threads exceeded");
uint active_workers = MAX2(1U, parallel_marking_threads());
CMRootRegionScanTask task(this);
_parallel_workers->set_active_workers(active_workers);
_parallel_workers->run_task(&task);
! if (G1Log::fine()) {
! gclog_or_tty->gclog_stamp();
! gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf secs]", os::elapsedTime() - scan_start);
! }
// It's possible that has_aborted() is true here without actually
// aborting the survivor scan earlier. This is OK as it's
// mainly used for sanity checking.
root_regions()->scan_finished();
--- 1068,1102 ----
}
}
};
void ConcurrentMark::scanRootRegions() {
! jlong scan_start = os::elapsed_counter();
// Start of concurrent marking.
ClassLoaderDataGraph::clear_claimed_marks();
// scan_in_progress() will have been set to true only if there was
// at least one root region to scan. So, if it's false, we
// should not attempt to do any further work.
if (root_regions()->scan_in_progress()) {
! log_info(gc)("Concurrent Root Region Scan (%.3fs)", TimeHelper::counter_to_seconds(scan_start));
_parallel_marking_threads = calc_parallel_marking_threads();
assert(parallel_marking_threads() <= max_parallel_marking_threads(),
"Maximum number of marking threads exceeded");
uint active_workers = MAX2(1U, parallel_marking_threads());
CMRootRegionScanTask task(this);
_parallel_workers->set_active_workers(active_workers);
_parallel_workers->run_task(&task);
! double end_time_ms = os::elapsed_counter();
! log_info(gc)("Concurrent Root Region Scan (%.3fs, %.3fs) %.3fms",
! TimeHelper::counter_to_seconds(scan_start),
! TimeHelper::counter_to_seconds(end_time_ms),
! TimeHelper::counter_to_millis(end_time_ms - scan_start));
// It's possible that has_aborted() is true here without actually
// aborting the survivor scan earlier. This is OK as it's
// mainly used for sanity checking.
root_regions()->scan_finished();
*** 1148,1173 ****
_parallel_workers->set_active_workers(active_workers);
_parallel_workers->run_task(&markingTask);
print_stats();
}
- // Helper class to get rid of some boilerplate code.
- class G1CMTraceTime : public StackObj {
- GCTraceTimeImpl _gc_trace_time;
- static bool doit_and_prepend(bool doit) {
- if (doit) {
- gclog_or_tty->put(' ');
- }
- return doit;
- }
-
- public:
- G1CMTraceTime(const char* title, bool doit)
- : _gc_trace_time(title, doit_and_prepend(doit), false, G1CollectedHeap::heap()->gc_timer_cm()) {
- }
- };
-
void ConcurrentMark::checkpointRootsFinal(bool clear_all_soft_refs) {
// world is stopped at this checkpoint
assert(SafepointSynchronize::is_at_safepoint(),
"world should be stopped");
--- 1129,1138 ----
*** 1182,1193 ****
SvcGCMarker sgcm(SvcGCMarker::OTHER);
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking,
! " VerifyDuringGC:(before)");
}
g1h->check_bitmaps("Remark Start");
G1CollectorPolicy* g1p = g1h->g1_policy();
g1p->record_concurrent_mark_remark_start();
--- 1147,1157 ----
SvcGCMarker sgcm(SvcGCMarker::OTHER);
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (before)");
}
g1h->check_bitmaps("Remark Start");
G1CollectorPolicy* g1p = g1h->g1_policy();
g1p->record_concurrent_mark_remark_start();
*** 1201,1228 ****
weakRefsWork(clear_all_soft_refs);
if (has_overflown()) {
// Oops. We overflowed. Restart concurrent marking.
_restart_for_overflow = true;
! if (G1TraceMarkStackOverflow) {
! gclog_or_tty->print_cr("\nRemark led to restart for overflow.");
! }
// Verify the heap w.r.t. the previous marking bitmap.
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking,
! " VerifyDuringGC:(overflow)");
}
// Clear the marking state because we will be restarting
// marking due to overflowing the global mark stack.
reset_marking_state();
} else {
{
! G1CMTraceTime trace("GC aggregate-data", G1Log::finer());
// Aggregate the per-task counting data that we have accumulated
// while marking.
aggregate_count_data();
}
--- 1165,1189 ----
weakRefsWork(clear_all_soft_refs);
if (has_overflown()) {
// Oops. We overflowed. Restart concurrent marking.
_restart_for_overflow = true;
! log_develop(gc)("Remark led to restart for overflow.");
// Verify the heap w.r.t. the previous marking bitmap.
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (overflow)");
}
// Clear the marking state because we will be restarting
// marking due to overflowing the global mark stack.
reset_marking_state();
} else {
{
! GCTraceTime(Debug, gc) trace("GC aggregate-data", g1h->gc_timer_cm());
// Aggregate the per-task counting data that we have accumulated
// while marking.
aggregate_count_data();
}
*** 1235,1246 ****
true /* expected_active */);
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UseNextMarking,
! " VerifyDuringGC:(after)");
}
g1h->check_bitmaps("Remark End");
assert(!restart_for_overflow(), "sanity");
// Completely reset the marking state since marking completed
set_non_marking_state();
--- 1196,1206 ----
true /* expected_active */);
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UseNextMarking, "During GC (after)");
}
g1h->check_bitmaps("Remark End");
assert(!restart_for_overflow(), "sanity");
// Completely reset the marking state since marking completed
set_non_marking_state();
*** 1755,1766 ****
g1h->verify_region_sets_optional();
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking,
! " VerifyDuringGC:(before)");
}
g1h->check_bitmaps("Cleanup Start");
G1CollectorPolicy* g1p = g1h->g1_policy();
g1p->record_concurrent_mark_cleanup_start();
--- 1715,1725 ----
g1h->verify_region_sets_optional();
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (before)");
}
g1h->check_bitmaps("Cleanup Start");
G1CollectorPolicy* g1p = g1h->g1_policy();
g1p->record_concurrent_mark_cleanup_start();
*** 1798,1809 ****
double count_end = os::elapsedTime();
double this_final_counting_time = (count_end - start);
_total_counting_time += this_final_counting_time;
! if (G1PrintRegionLivenessInfo) {
! G1PrintRegionLivenessInfoClosure cl(gclog_or_tty, "Post-Marking");
_g1h->heap_region_iterate(&cl);
}
// Install newly created mark bitMap as "prev".
swapMarkBitMaps();
--- 1757,1768 ----
double count_end = os::elapsedTime();
double this_final_counting_time = (count_end - start);
_total_counting_time += this_final_counting_time;
! if (Log<LOG_TAGS(gc, liveness)>::is_trace()) {
! G1PrintRegionLivenessInfoClosure cl("Post-Marking");
_g1h->heap_region_iterate(&cl);
}
// Install newly created mark bitMap as "prev".
swapMarkBitMaps();
*** 1842,1864 ****
// Statistics.
double end = os::elapsedTime();
_cleanup_times.add((end - start) * 1000.0);
- if (G1Log::fine()) {
- g1h->g1_policy()->print_heap_transition(start_used_bytes);
- }
-
// Clean up will have freed any regions completely full of garbage.
// Update the soft reference policy with the new heap occupancy.
Universe::update_heap_info_at_gc();
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking,
! " VerifyDuringGC:(after)");
}
g1h->check_bitmaps("Cleanup End");
g1h->verify_region_sets_optional();
--- 1801,1818 ----
// Statistics.
double end = os::elapsedTime();
_cleanup_times.add((end - start) * 1000.0);
// Clean up will have freed any regions completely full of garbage.
// Update the soft reference policy with the new heap occupancy.
Universe::update_heap_info_at_gc();
if (VerifyDuringGC) {
HandleMark hm; // handle scope
g1h->prepare_for_verify();
! Universe::verify(VerifyOption_G1UsePrevMarking, "During GC (after)");
}
g1h->check_bitmaps("Cleanup End");
g1h->verify_region_sets_optional();
*** 1887,1901 ****
G1CollectedHeap* g1h = G1CollectedHeap::heap();
_cleanup_list.verify_optional();
FreeRegionList tmp_free_list("Tmp Free List");
! if (G1ConcRegionFreeingVerbose) {
! gclog_or_tty->print_cr("G1ConcRegionFreeing [complete cleanup] : "
"cleanup list has %u entries",
_cleanup_list.length());
- }
// No one else should be accessing the _cleanup_list at this point,
// so it is not necessary to take any locks
while (!_cleanup_list.is_empty()) {
HeapRegion* hr = _cleanup_list.remove_region(true /* from_head */);
--- 1841,1853 ----
G1CollectedHeap* g1h = G1CollectedHeap::heap();
_cleanup_list.verify_optional();
FreeRegionList tmp_free_list("Tmp Free List");
! log_develop(gc, freelist)("G1ConcRegionFreeing [complete cleanup] : "
"cleanup list has %u entries",
_cleanup_list.length());
// No one else should be accessing the _cleanup_list at this point,
// so it is not necessary to take any locks
while (!_cleanup_list.is_empty()) {
HeapRegion* hr = _cleanup_list.remove_region(true /* from_head */);
*** 1909,1925 ****
// we do during this process. We'll also append the local list when
// _cleanup_list is empty (which means we just removed the last
// region from the _cleanup_list).
if ((tmp_free_list.length() % G1SecondaryFreeListAppendLength == 0) ||
_cleanup_list.is_empty()) {
! if (G1ConcRegionFreeingVerbose) {
! gclog_or_tty->print_cr("G1ConcRegionFreeing [complete cleanup] : "
"appending %u entries to the secondary_free_list, "
"cleanup list still has %u entries",
tmp_free_list.length(),
_cleanup_list.length());
- }
{
MutexLockerEx x(SecondaryFreeList_lock, Mutex::_no_safepoint_check_flag);
g1h->secondary_free_list_add(&tmp_free_list);
SecondaryFreeList_lock->notify_all();
--- 1861,1875 ----
// we do during this process. We'll also append the local list when
// _cleanup_list is empty (which means we just removed the last
// region from the _cleanup_list).
if ((tmp_free_list.length() % G1SecondaryFreeListAppendLength == 0) ||
_cleanup_list.is_empty()) {
! log_develop(gc, freelist)("G1ConcRegionFreeing [complete cleanup] : "
"appending %u entries to the secondary_free_list, "
"cleanup list still has %u entries",
tmp_free_list.length(),
_cleanup_list.length());
{
MutexLockerEx x(SecondaryFreeList_lock, Mutex::_no_safepoint_check_flag);
g1h->secondary_free_list_add(&tmp_free_list);
SecondaryFreeList_lock->notify_all();
*** 2172,2182 ****
G1CMIsAliveClosure g1_is_alive(g1h);
// Inner scope to exclude the cleaning of the string and symbol
// tables from the displayed time.
{
! G1CMTraceTime t("GC ref-proc", G1Log::finer());
ReferenceProcessor* rp = g1h->ref_processor_cm();
// See the comment in G1CollectedHeap::ref_processing_init()
// about how reference processing currently works in G1.
--- 2122,2132 ----
G1CMIsAliveClosure g1_is_alive(g1h);
// Inner scope to exclude the cleaning of the string and symbol
// tables from the displayed time.
{
! GCTraceTime(Debug, gc) trace("GC ref-proc", g1h->gc_timer_cm());
ReferenceProcessor* rp = g1h->ref_processor_cm();
// See the comment in G1CollectedHeap::ref_processing_init()
// about how reference processing currently works in G1.
*** 2262,2289 ****
assert(_markStack.isEmpty(), "Marking should have completed");
// Unload Klasses, String, Symbols, Code Cache, etc.
{
! G1CMTraceTime trace("Unloading", G1Log::finer());
if (ClassUnloadingWithConcurrentMark) {
bool purged_classes;
{
! G1CMTraceTime trace("System Dictionary Unloading", G1Log::finest());
purged_classes = SystemDictionary::do_unloading(&g1_is_alive, false /* Defer klass cleaning */);
}
{
! G1CMTraceTime trace("Parallel Unloading", G1Log::finest());
weakRefsWorkParallelPart(&g1_is_alive, purged_classes);
}
}
if (G1StringDedup::is_enabled()) {
! G1CMTraceTime trace("String Deduplication Unlink", G1Log::finest());
G1StringDedup::unlink(&g1_is_alive);
}
}
}
--- 2212,2239 ----
assert(_markStack.isEmpty(), "Marking should have completed");
// Unload Klasses, String, Symbols, Code Cache, etc.
{
! GCTraceTime(Debug, gc) trace("Unloading", g1h->gc_timer_cm());
if (ClassUnloadingWithConcurrentMark) {
bool purged_classes;
{
! GCTraceTime(Trace, gc) trace("System Dictionary Unloading", g1h->gc_timer_cm());
purged_classes = SystemDictionary::do_unloading(&g1_is_alive, false /* Defer klass cleaning */);
}
{
! GCTraceTime(Trace, gc) trace("Parallel Unloading", g1h->gc_timer_cm());
weakRefsWorkParallelPart(&g1_is_alive, purged_classes);
}
}
if (G1StringDedup::is_enabled()) {
! GCTraceTime(Trace, gc) trace("String Deduplication Unlink", g1h->gc_timer_cm());
G1StringDedup::unlink(&g1_is_alive);
}
}
}
*** 2400,2410 ****
void ConcurrentMark::checkpointRootsFinalWork() {
ResourceMark rm;
HandleMark hm;
G1CollectedHeap* g1h = G1CollectedHeap::heap();
! G1CMTraceTime trace("Finalize Marking", G1Log::finer());
g1h->ensure_parsability(false);
// this is remark, so we'll use up all active threads
uint active_workers = g1h->workers()->active_workers();
--- 2350,2360 ----
void ConcurrentMark::checkpointRootsFinalWork() {
ResourceMark rm;
HandleMark hm;
G1CollectedHeap* g1h = G1CollectedHeap::heap();
! GCTraceTime(Debug, gc) trace("Finalize Marking", g1h->gc_timer_cm());
g1h->ensure_parsability(false);
// this is remark, so we'll use up all active threads
uint active_workers = g1h->workers()->active_workers();
*** 2717,2732 ****
task_card_bm->clear();
}
}
void ConcurrentMark::print_stats() {
! if (G1MarkingVerboseLevel > 0) {
! gclog_or_tty->print_cr("---------------------------------------------------------------------");
for (size_t i = 0; i < _active_tasks; ++i) {
_tasks[i]->print_stats();
! gclog_or_tty->print_cr("---------------------------------------------------------------------");
! }
}
}
// abandon current marking iteration due to a Full GC
void ConcurrentMark::abort() {
--- 2667,2684 ----
task_card_bm->clear();
}
}
void ConcurrentMark::print_stats() {
! LogHandle(gc, stats) log;
! if (!log.is_debug()) {
! return;
! }
! log.debug("---------------------------------------------------------------------");
for (size_t i = 0; i < _active_tasks; ++i) {
_tasks[i]->print_stats();
! log.debug("---------------------------------------------------------------------");
}
}
// abandon current marking iteration due to a Full GC
void ConcurrentMark::abort() {
*** 2766,2812 ****
_g1h->register_concurrent_cycle_end();
}
static void print_ms_time_info(const char* prefix, const char* name,
NumberSeq& ns) {
! gclog_or_tty->print_cr("%s%5d %12s: total time = %8.2f s (avg = %8.2f ms).",
prefix, ns.num(), name, ns.sum()/1000.0, ns.avg());
if (ns.num() > 0) {
! gclog_or_tty->print_cr("%s [std. dev = %8.2f ms, max = %8.2f ms]",
prefix, ns.sd(), ns.maximum());
}
}
void ConcurrentMark::print_summary_info() {
! gclog_or_tty->print_cr(" Concurrent marking:");
print_ms_time_info(" ", "init marks", _init_times);
print_ms_time_info(" ", "remarks", _remark_times);
{
print_ms_time_info(" ", "final marks", _remark_mark_times);
print_ms_time_info(" ", "weak refs", _remark_weak_ref_times);
}
print_ms_time_info(" ", "cleanups", _cleanup_times);
! gclog_or_tty->print_cr(" Final counting total time = %8.2f s (avg = %8.2f ms).",
! _total_counting_time,
! (_cleanup_times.num() > 0 ? _total_counting_time * 1000.0 /
! (double)_cleanup_times.num()
! : 0.0));
if (G1ScrubRemSets) {
! gclog_or_tty->print_cr(" RS scrub total time = %8.2f s (avg = %8.2f ms).",
! _total_rs_scrub_time,
! (_cleanup_times.num() > 0 ? _total_rs_scrub_time * 1000.0 /
! (double)_cleanup_times.num()
! : 0.0));
! }
! gclog_or_tty->print_cr(" Total stop_world time = %8.2f s.",
! (_init_times.sum() + _remark_times.sum() +
! _cleanup_times.sum())/1000.0);
! gclog_or_tty->print_cr(" Total concurrent time = %8.2f s "
! "(%8.2f s marking).",
! cmThread()->vtime_accum(),
! cmThread()->vtime_mark_accum());
}
void ConcurrentMark::print_worker_threads_on(outputStream* st) const {
_parallel_workers->print_worker_threads_on(st);
}
--- 2718,2760 ----
_g1h->register_concurrent_cycle_end();
}
static void print_ms_time_info(const char* prefix, const char* name,
NumberSeq& ns) {
! log_trace(gc, marking, stats, exit)("%s%5d %12s: total time = %8.2f s (avg = %8.2f ms).",
prefix, ns.num(), name, ns.sum()/1000.0, ns.avg());
if (ns.num() > 0) {
! log_trace(gc, marking, stats, exit)("%s [std. dev = %8.2f ms, max = %8.2f ms]",
prefix, ns.sd(), ns.maximum());
}
}
void ConcurrentMark::print_summary_info() {
! LogHandle(gc, marking, stats, exit) log;
! if (!log.is_trace()) {
! return;
! }
!
! log.trace(" Concurrent marking:");
print_ms_time_info(" ", "init marks", _init_times);
print_ms_time_info(" ", "remarks", _remark_times);
{
print_ms_time_info(" ", "final marks", _remark_mark_times);
print_ms_time_info(" ", "weak refs", _remark_weak_ref_times);
}
print_ms_time_info(" ", "cleanups", _cleanup_times);
! log.trace(" Final counting total time = %8.2f s (avg = %8.2f ms).",
! _total_counting_time, (_cleanup_times.num() > 0 ? _total_counting_time * 1000.0 / (double)_cleanup_times.num() : 0.0));
if (G1ScrubRemSets) {
! log.trace(" RS scrub total time = %8.2f s (avg = %8.2f ms).",
! _total_rs_scrub_time, (_cleanup_times.num() > 0 ? _total_rs_scrub_time * 1000.0 / (double)_cleanup_times.num() : 0.0));
! }
! log.trace(" Total stop_world time = %8.2f s.",
! (_init_times.sum() + _remark_times.sum() + _cleanup_times.sum())/1000.0);
! log.trace(" Total concurrent time = %8.2f s (%8.2f s marking).",
! cmThread()->vtime_accum(), cmThread()->vtime_mark_accum());
}
void ConcurrentMark::print_worker_threads_on(outputStream* st) const {
_parallel_workers->print_worker_threads_on(st);
}
*** 3182,3199 ****
// limits to get the regular clock call early
decrease_limits();
}
void CMTask::print_stats() {
! gclog_or_tty->print_cr("Marking Stats, task = %u, calls = %d",
_worker_id, _calls);
! gclog_or_tty->print_cr(" Elapsed time = %1.2lfms, Termination time = %1.2lfms",
_elapsed_time_ms, _termination_time_ms);
! gclog_or_tty->print_cr(" Step Times (cum): num = %d, avg = %1.2lfms, sd = %1.2lfms",
_step_times_ms.num(), _step_times_ms.avg(),
_step_times_ms.sd());
! gclog_or_tty->print_cr(" max = %1.2lfms, total = %1.2lfms",
_step_times_ms.maximum(), _step_times_ms.sum());
}
bool ConcurrentMark::try_stealing(uint worker_id, int* hash_seed, oop& obj) {
return _task_queues->steal(worker_id, hash_seed, obj);
--- 3130,3147 ----
// limits to get the regular clock call early
decrease_limits();
}
void CMTask::print_stats() {
! log_debug(gc, stats)("Marking Stats, task = %u, calls = %d",
_worker_id, _calls);
! log_debug(gc, stats)(" Elapsed time = %1.2lfms, Termination time = %1.2lfms",
_elapsed_time_ms, _termination_time_ms);
! log_debug(gc, stats)(" Step Times (cum): num = %d, avg = %1.2lfms, sd = %1.2lfms",
_step_times_ms.num(), _step_times_ms.avg(),
_step_times_ms.sd());
! log_debug(gc, stats)(" max = %1.2lfms, total = %1.2lfms",
_step_times_ms.maximum(), _step_times_ms.sum());
}
bool ConcurrentMark::try_stealing(uint worker_id, int* hash_seed, oop& obj) {
return _task_queues->steal(worker_id, hash_seed, obj);
*** 3699,3729 ****
#define G1PPRL_SUM_BYTE_FORMAT(tag) " " tag ": " SIZE_FORMAT
#define G1PPRL_SUM_MB_FORMAT(tag) " " tag ": %1.2f MB"
#define G1PPRL_SUM_MB_PERC_FORMAT(tag) G1PPRL_SUM_MB_FORMAT(tag) " / %1.2f %%"
G1PrintRegionLivenessInfoClosure::
! G1PrintRegionLivenessInfoClosure(outputStream* out, const char* phase_name)
! : _out(out),
! _total_used_bytes(0), _total_capacity_bytes(0),
_total_prev_live_bytes(0), _total_next_live_bytes(0),
_hum_used_bytes(0), _hum_capacity_bytes(0),
_hum_prev_live_bytes(0), _hum_next_live_bytes(0),
_total_remset_bytes(0), _total_strong_code_roots_bytes(0) {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
MemRegion g1_reserved = g1h->g1_reserved();
double now = os::elapsedTime();
// Print the header of the output.
! _out->cr();
! _out->print_cr(G1PPRL_LINE_PREFIX" PHASE %s @ %1.3f", phase_name, now);
! _out->print_cr(G1PPRL_LINE_PREFIX" HEAP"
G1PPRL_SUM_ADDR_FORMAT("reserved")
G1PPRL_SUM_BYTE_FORMAT("region-size"),
p2i(g1_reserved.start()), p2i(g1_reserved.end()),
HeapRegion::GrainBytes);
! _out->print_cr(G1PPRL_LINE_PREFIX);
! _out->print_cr(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_H_FORMAT
G1PPRL_ADDR_BASE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
--- 3647,3675 ----
#define G1PPRL_SUM_BYTE_FORMAT(tag) " " tag ": " SIZE_FORMAT
#define G1PPRL_SUM_MB_FORMAT(tag) " " tag ": %1.2f MB"
#define G1PPRL_SUM_MB_PERC_FORMAT(tag) G1PPRL_SUM_MB_FORMAT(tag) " / %1.2f %%"
G1PrintRegionLivenessInfoClosure::
! G1PrintRegionLivenessInfoClosure(const char* phase_name)
! : _total_used_bytes(0), _total_capacity_bytes(0),
_total_prev_live_bytes(0), _total_next_live_bytes(0),
_hum_used_bytes(0), _hum_capacity_bytes(0),
_hum_prev_live_bytes(0), _hum_next_live_bytes(0),
_total_remset_bytes(0), _total_strong_code_roots_bytes(0) {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
MemRegion g1_reserved = g1h->g1_reserved();
double now = os::elapsedTime();
// Print the header of the output.
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX" PHASE %s @ %1.3f", phase_name, now);
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX" HEAP"
G1PPRL_SUM_ADDR_FORMAT("reserved")
G1PPRL_SUM_BYTE_FORMAT("region-size"),
p2i(g1_reserved.start()), p2i(g1_reserved.end()),
HeapRegion::GrainBytes);
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX);
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_H_FORMAT
G1PPRL_ADDR_BASE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
*** 3731,3741 ****
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT,
"type", "address-range",
"used", "prev-live", "next-live", "gc-eff",
"remset", "code-roots");
! _out->print_cr(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_H_FORMAT
G1PPRL_ADDR_BASE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
--- 3677,3687 ----
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT,
"type", "address-range",
"used", "prev-live", "next-live", "gc-eff",
"remset", "code-roots");
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_H_FORMAT
G1PPRL_ADDR_BASE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
G1PPRL_BYTE_H_FORMAT
*** 3813,3823 ****
_total_next_live_bytes += next_live_bytes;
_total_remset_bytes += remset_bytes;
_total_strong_code_roots_bytes += strong_code_roots_bytes;
// Print a line for this particular region.
! _out->print_cr(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_FORMAT
G1PPRL_ADDR_BASE_FORMAT
G1PPRL_BYTE_FORMAT
G1PPRL_BYTE_FORMAT
G1PPRL_BYTE_FORMAT
--- 3759,3769 ----
_total_next_live_bytes += next_live_bytes;
_total_remset_bytes += remset_bytes;
_total_strong_code_roots_bytes += strong_code_roots_bytes;
// Print a line for this particular region.
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
G1PPRL_TYPE_FORMAT
G1PPRL_ADDR_BASE_FORMAT
G1PPRL_BYTE_FORMAT
G1PPRL_BYTE_FORMAT
G1PPRL_BYTE_FORMAT
*** 3833,3844 ****
G1PrintRegionLivenessInfoClosure::~G1PrintRegionLivenessInfoClosure() {
// add static memory usages to remembered set sizes
_total_remset_bytes += HeapRegionRemSet::fl_mem_size() + HeapRegionRemSet::static_mem_size();
// Print the footer of the output.
! _out->print_cr(G1PPRL_LINE_PREFIX);
! _out->print_cr(G1PPRL_LINE_PREFIX
" SUMMARY"
G1PPRL_SUM_MB_FORMAT("capacity")
G1PPRL_SUM_MB_PERC_FORMAT("used")
G1PPRL_SUM_MB_PERC_FORMAT("prev-live")
G1PPRL_SUM_MB_PERC_FORMAT("next-live")
--- 3779,3790 ----
G1PrintRegionLivenessInfoClosure::~G1PrintRegionLivenessInfoClosure() {
// add static memory usages to remembered set sizes
_total_remset_bytes += HeapRegionRemSet::fl_mem_size() + HeapRegionRemSet::static_mem_size();
// Print the footer of the output.
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX);
! log_trace(gc, liveness)(G1PPRL_LINE_PREFIX
" SUMMARY"
G1PPRL_SUM_MB_FORMAT("capacity")
G1PPRL_SUM_MB_PERC_FORMAT("used")
G1PPRL_SUM_MB_PERC_FORMAT("prev-live")
G1PPRL_SUM_MB_PERC_FORMAT("next-live")
*** 3851,3857 ****
perc(_total_prev_live_bytes, _total_capacity_bytes),
bytes_to_mb(_total_next_live_bytes),
perc(_total_next_live_bytes, _total_capacity_bytes),
bytes_to_mb(_total_remset_bytes),
bytes_to_mb(_total_strong_code_roots_bytes));
- _out->cr();
}
--- 3797,3802 ----
< prev index next >