提交 f50306ac 编写于 作者: B brutisso

Merge

/*
* Copyright (c) 1999, 2010, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 1999, 2012, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
......@@ -202,7 +202,7 @@ class Bsd {
static void fast_thread_clock_init(void);
#endif
static bool supports_monotonic_clock() {
static inline bool supports_monotonic_clock() {
return _clock_gettime != NULL;
}
......
/*
* Copyright (c) 1999, 2010, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 1999, 2012, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
......@@ -178,7 +178,7 @@ class Linux {
// fast POSIX clocks support
static void fast_thread_clock_init(void);
static bool supports_monotonic_clock() {
static inline bool supports_monotonic_clock() {
return _clock_gettime != NULL;
}
......
......@@ -1246,6 +1246,31 @@ void G1CollectedHeap::print_hrs_post_compaction() {
heap_region_iterate(&cl);
}
double G1CollectedHeap::verify(bool guard, const char* msg) {
double verify_time_ms = 0.0;
if (guard && total_collections() >= VerifyGCStartAt) {
double verify_start = os::elapsedTime();
HandleMark hm; // Discard invalid handles created during verification
gclog_or_tty->print(msg);
prepare_for_verify();
Universe::verify(false /* silent */, VerifyOption_G1UsePrevMarking);
verify_time_ms = (os::elapsedTime() - verify_start) * 1000;
}
return verify_time_ms;
}
void G1CollectedHeap::verify_before_gc() {
double verify_time_ms = verify(VerifyBeforeGC, " VerifyBeforeGC:");
g1_policy()->phase_times()->record_verify_before_time_ms(verify_time_ms);
}
void G1CollectedHeap::verify_after_gc() {
double verify_time_ms = verify(VerifyAfterGC, " VerifyAfterGC:");
g1_policy()->phase_times()->record_verify_after_time_ms(verify_time_ms);
}
bool G1CollectedHeap::do_collection(bool explicit_gc,
bool clear_all_soft_refs,
size_t word_size) {
......@@ -1304,14 +1329,8 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
size_t g1h_prev_used = used();
assert(used() == recalculate_used(), "Should be equal");
if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
gclog_or_tty->print(" VerifyBeforeGC:");
prepare_for_verify();
Universe::verify(/* silent */ false,
/* option */ VerifyOption_G1UsePrevMarking);
verify_before_gc();
}
pre_full_gc_dump();
COMPILER2_PRESENT(DerivedPointerTable::clear());
......@@ -1378,14 +1397,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
MemoryService::track_memory_usage();
if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
gclog_or_tty->print(" VerifyAfterGC:");
prepare_for_verify();
Universe::verify(/* silent */ false,
/* option */ VerifyOption_G1UsePrevMarking);
}
verify_after_gc();
assert(!ref_processor_stw()->discovery_enabled(), "Postcondition");
ref_processor_stw()->verify_no_references_recorded();
......@@ -1933,6 +1945,9 @@ G1CollectedHeap::G1CollectedHeap(G1CollectorPolicy* policy_) :
clear_cset_start_regions();
// Initialize the G1EvacuationFailureALot counters and flags.
NOT_PRODUCT(reset_evacuation_should_fail();)
guarantee(_task_queues != NULL, "task_queues allocation failure.");
#ifdef SPARC
// Issue a stern warning, but allow use for experimentation and debugging.
......@@ -2327,8 +2342,7 @@ void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl,
while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) {
n_completed_buffers++;
}
g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i,
(double) n_completed_buffers);
g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i, n_completed_buffers);
dcqs.clear_n_completed_buffers();
assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!");
}
......@@ -3735,8 +3749,9 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
workers()->active_workers() : 1);
g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers,
g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause());
double pause_start_sec = os::elapsedTime();
g1_policy()->phase_times()->note_gc_start(active_workers);
bool initial_mark_gc = g1_policy()->during_initial_mark_pause();
TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
......@@ -3765,13 +3780,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
increment_total_collections(false /* full gc */);
increment_gc_time_stamp();
if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
gclog_or_tty->print(" VerifyBeforeGC:");
prepare_for_verify();
Universe::verify(/* silent */ false,
/* option */ VerifyOption_G1UsePrevMarking);
}
verify_before_gc();
COMPILER2_PRESENT(DerivedPointerTable::clear());
......@@ -3984,10 +3993,6 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
true /* verify_fingers */);
_cm->note_end_of_gc();
// Collect thread local data to allow the ergonomics to use
// the collected information
g1_policy()->phase_times()->collapse_par_times();
// This timing is only used by the ergonomics to handle our pause target.
// It is unclear why this should not include the full pause. We will
// investigate this in CR 7178365.
......@@ -4020,13 +4025,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
// scanning cards (see CR 7039627).
increment_gc_time_stamp();
if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) {
HandleMark hm; // Discard invalid handles created during verification
gclog_or_tty->print(" VerifyAfterGC:");
prepare_for_verify();
Universe::verify(/* silent */ false,
/* option */ VerifyOption_G1UsePrevMarking);
}
verify_after_gc();
assert(!ref_processor_stw()->discovery_enabled(), "Postcondition");
ref_processor_stw()->verify_no_references_recorded();
......@@ -4050,10 +4049,35 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
gc_epilogue(false);
g1_policy()->phase_times()->note_gc_end(os::elapsedTime());
if (G1Log::fine()) {
if (PrintGCTimeStamps) {
gclog_or_tty->stamp();
gclog_or_tty->print(": ");
}
GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
.append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
.append(initial_mark_gc ? " (initial-mark)" : "");
// We have to do this after we decide whether to expand the heap or not.
double pause_time_sec = os::elapsedTime() - pause_start_sec;
if (G1Log::finer()) {
if (evacuation_failed()) {
gc_cause_str.append(" (to-space exhausted)");
}
gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_sec);
g1_policy()->phase_times()->note_gc_end();
g1_policy()->phase_times()->print(pause_time_sec);
g1_policy()->print_detailed_heap_transition();
} else {
if (evacuation_failed()) {
gc_cause_str.append("--");
}
gclog_or_tty->print("[%s", (const char*)gc_cause_str);
g1_policy()->print_heap_transition();
gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec);
}
}
}
// It is not yet to safe to tell the concurrent mark to
......@@ -4543,7 +4567,15 @@ oop G1ParCopyClosure<do_gen_barrier, barrier, do_mark_object>
GCAllocPurpose alloc_purpose = g1p->evacuation_destination(from_region, age,
word_sz);
HeapWord* obj_ptr = _par_scan_state->allocate(alloc_purpose, word_sz);
oop obj = oop(obj_ptr);
#ifndef PRODUCT
// Should this evacuation fail?
if (_g1->evacuation_should_fail()) {
if (obj_ptr != NULL) {
_par_scan_state->undo_allocation(alloc_purpose, obj_ptr, word_sz);
obj_ptr = NULL;
}
}
#endif // !PRODUCT
if (obj_ptr == NULL) {
// This will either forward-to-self, or detect that someone else has
......@@ -4552,6 +4584,8 @@ oop G1ParCopyClosure<do_gen_barrier, barrier, do_mark_object>
return _g1->handle_evacuation_failure_par(cl, old);
}
oop obj = oop(obj_ptr);
// We're going to allocate linearly, so might as well prefetch ahead.
Prefetch::write(obj_ptr, PrefetchCopyIntervalInBytes);
......@@ -4863,7 +4897,7 @@ public:
evac.do_void();
double elapsed_ms = (os::elapsedTime()-start)*1000.0;
double term_ms = pss.term_time()*1000.0;
_g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms);
_g1h->g1_policy()->phase_times()->add_obj_copy_time(worker_id, elapsed_ms-term_ms);
_g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts());
}
_g1h->g1_policy()->record_thread_age_table(pss.age_table());
......@@ -4991,27 +5025,28 @@ g1_process_strong_roots(bool collecting_perm_gen,
buf_scan_non_heap_roots.done();
buf_scan_perm.done();
double ext_roots_end = os::elapsedTime();
g1_policy()->phase_times()->reset_obj_copy_time(worker_i);
double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() +
buf_scan_non_heap_roots.closure_app_seconds();
g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0);
double ext_root_time_ms =
((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0;
((os::elapsedTime() - ext_roots_start) - obj_copy_time_sec) * 1000.0;
g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
// During conc marking we have to filter the per-thread SATB buffers
// to make sure we remove any oops into the CSet (which will show up
// as implicitly live).
double satb_filtering_ms = 0.0;
if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) {
if (mark_in_progress()) {
double satb_filter_start = os::elapsedTime();
JavaThread::satb_mark_queue_set().filter_thread_buffers();
satb_filtering_ms = (os::elapsedTime() - satb_filter_start) * 1000.0;
}
}
double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0;
g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms);
// Now scan the complement of the collection set.
......@@ -5556,6 +5591,9 @@ void G1CollectedHeap::evacuate_collection_set() {
_expand_heap_after_alloc_failure = true;
set_evacuation_failed(false);
// Should G1EvacuationFailureALot be in effect for this GC?
NOT_PRODUCT(set_evacuation_failure_alot_for_current_gc();)
g1_rem_set()->prepare_for_oops_into_collection_set_do();
concurrent_g1_refine()->set_use_cache(false);
concurrent_g1_refine()->clear_hot_cache_claimed_index();
......@@ -5647,11 +5685,11 @@ void G1CollectedHeap::evacuate_collection_set() {
if (evacuation_failed()) {
remove_self_forwarding_pointers();
if (G1Log::finer()) {
gclog_or_tty->print(" (to-space exhausted)");
} else if (G1Log::fine()) {
gclog_or_tty->print("--");
}
// Reset the G1EvacuationFailureALot counters and flags
// Note: the values are reset only when an actual
// evacuation failure occurs.
NOT_PRODUCT(reset_evacuation_should_fail();)
}
// Enqueue any remaining references remaining on the STW
......
......@@ -405,6 +405,10 @@ private:
// heap after a compaction.
void print_hrs_post_compaction();
double verify(bool guard, const char* msg);
void verify_before_gc();
void verify_after_gc();
// These are macros so that, if the assert fires, we get the correct
// line number, file, etc.
......@@ -911,6 +915,39 @@ protected:
oop handle_evacuation_failure_par(OopsInHeapRegionClosure* cl, oop obj);
void handle_evacuation_failure_common(oop obj, markOop m);
#ifndef PRODUCT
// Support for forcing evacuation failures. Analogous to
// PromotionFailureALot for the other collectors.
// Records whether G1EvacuationFailureALot should be in effect
// for the current GC
bool _evacuation_failure_alot_for_current_gc;
// Used to record the GC number for interval checking when
// determining whether G1EvaucationFailureALot is in effect
// for the current GC.
size_t _evacuation_failure_alot_gc_number;
// Count of the number of evacuations between failures.
volatile size_t _evacuation_failure_alot_count;
// Set whether G1EvacuationFailureALot should be in effect
// for the current GC (based upon the type of GC and which
// command line flags are set);
inline bool evacuation_failure_alot_for_gc_type(bool gcs_are_young,
bool during_initial_mark,
bool during_marking);
inline void set_evacuation_failure_alot_for_current_gc();
// Return true if it's time to cause an evacuation failure.
inline bool evacuation_should_fail();
// Reset the G1EvacuationFailureALot counters. Should be called at
// the end of an evacuation pause in which an evacuation failure ocurred.
inline void reset_evacuation_should_fail();
#endif // !PRODUCT
// ("Weak") Reference processing support.
//
// G1 has 2 instances of the referece processor class. One
......
/*
* Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
......@@ -138,7 +138,7 @@ inline RefToScanQueue* G1CollectedHeap::task_queue(int i) const {
return _task_queues->queue(i);
}
inline bool G1CollectedHeap::isMarkedPrev(oop obj) const {
inline bool G1CollectedHeap::isMarkedPrev(oop obj) const {
return _cm->prevMarkBitMap()->isMarked((HeapWord *)obj);
}
......@@ -146,4 +146,77 @@ inline bool G1CollectedHeap::isMarkedNext(oop obj) const {
return _cm->nextMarkBitMap()->isMarked((HeapWord *)obj);
}
#ifndef PRODUCT
// Support for G1EvacuationFailureALot
inline bool
G1CollectedHeap::evacuation_failure_alot_for_gc_type(bool gcs_are_young,
bool during_initial_mark,
bool during_marking) {
bool res = false;
if (during_marking) {
res |= G1EvacuationFailureALotDuringConcMark;
}
if (during_initial_mark) {
res |= G1EvacuationFailureALotDuringInitialMark;
}
if (gcs_are_young) {
res |= G1EvacuationFailureALotDuringYoungGC;
} else {
// GCs are mixed
res |= G1EvacuationFailureALotDuringMixedGC;
}
return res;
}
inline void
G1CollectedHeap::set_evacuation_failure_alot_for_current_gc() {
if (G1EvacuationFailureALot) {
// Note we can't assert that _evacuation_failure_alot_for_current_gc
// is clear here. It may have been set during a previous GC but that GC
// did not copy enough objects (i.e. G1EvacuationFailureALotCount) to
// trigger an evacuation failure and clear the flags and and counts.
// Check if we have gone over the interval.
const size_t gc_num = total_collections();
const size_t elapsed_gcs = gc_num - _evacuation_failure_alot_gc_number;
_evacuation_failure_alot_for_current_gc = (elapsed_gcs >= G1EvacuationFailureALotInterval);
// Now check if G1EvacuationFailureALot is enabled for the current GC type.
const bool gcs_are_young = g1_policy()->gcs_are_young();
const bool during_im = g1_policy()->during_initial_mark_pause();
const bool during_marking = mark_in_progress();
_evacuation_failure_alot_for_current_gc &=
evacuation_failure_alot_for_gc_type(gcs_are_young,
during_im,
during_marking);
}
}
inline bool
G1CollectedHeap::evacuation_should_fail() {
if (!G1EvacuationFailureALot || !_evacuation_failure_alot_for_current_gc) {
return false;
}
// G1EvacuationFailureALot is in effect for current GC
// Access to _evacuation_failure_alot_count is not atomic;
// the value does not have to be exact.
if (++_evacuation_failure_alot_count < G1EvacuationFailureALotCount) {
return false;
}
_evacuation_failure_alot_count = 0;
return true;
}
inline void G1CollectedHeap::reset_evacuation_should_fail() {
if (G1EvacuationFailureALot) {
_evacuation_failure_alot_gc_number = total_collections();
_evacuation_failure_alot_count = 0;
_evacuation_failure_alot_for_current_gc = false;
}
}
#endif // #ifndef PRODUCT
#endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1COLLECTEDHEAP_INLINE_HPP
......@@ -795,7 +795,7 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
_trace_gen0_time_data.record_start_collection(s_w_t_ms);
_stop_world_start = 0.0;
phase_times()->_cur_collection_start_sec = start_time_sec;
phase_times()->record_cur_collection_start_sec(start_time_sec);
_cur_collection_pause_used_at_start_bytes = start_used;
_cur_collection_pause_used_regions_at_start = _g1->used_regions();
_pending_cards = _g1->pending_card_num();
......@@ -947,7 +947,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
_trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
// this is where we update the allocation rate of the application
double app_time_ms =
(phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
(phase_times()->cur_collection_start_sec() * 1000.0 - _prev_collection_pause_end_ms);
if (app_time_ms < MIN_TIMER_GRANULARITY) {
// This usually happens due to the timer not having the required
// granularity. Some Linuxes are the usual culprits.
......@@ -1035,7 +1035,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
if (update_stats) {
double cost_per_card_ms = 0.0;
if (_pending_cards > 0) {
cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards;
cost_per_card_ms = phase_times()->average_last_update_rs_time() / (double) _pending_cards;
_cost_per_card_ms_seq->add(cost_per_card_ms);
}
......@@ -1043,7 +1043,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
double cost_per_entry_ms = 0.0;
if (cards_scanned > 10) {
cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned;
cost_per_entry_ms = phase_times()->average_last_scan_rs_time() / (double) cards_scanned;
if (_last_gc_was_young) {
_cost_per_entry_ms_seq->add(cost_per_entry_ms);
} else {
......@@ -1083,7 +1083,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
size_t copied_bytes = surviving_bytes;
double cost_per_byte_ms = 0.0;
if (copied_bytes > 0) {
cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes;
cost_per_byte_ms = phase_times()->average_last_obj_copy_time() / (double) copied_bytes;
if (_in_marking_window) {
_cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
} else {
......@@ -1092,21 +1092,22 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
}
double all_other_time_ms = pause_time_ms -
(phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time);
(phase_times()->average_last_update_rs_time() + phase_times()->average_last_scan_rs_time()
+ phase_times()->average_last_obj_copy_time() + phase_times()->average_last_termination_time());
double young_other_time_ms = 0.0;
if (young_cset_region_length() > 0) {
young_other_time_ms =
phase_times()->_recorded_young_cset_choice_time_ms +
phase_times()->_recorded_young_free_cset_time_ms;
phase_times()->young_cset_choice_time_ms() +
phase_times()->young_free_cset_time_ms();
_young_other_cost_per_region_ms_seq->add(young_other_time_ms /
(double) young_cset_region_length());
}
double non_young_other_time_ms = 0.0;
if (old_cset_region_length() > 0) {
non_young_other_time_ms =
phase_times()->_recorded_non_young_cset_choice_time_ms +
phase_times()->_recorded_non_young_free_cset_time_ms;
phase_times()->non_young_cset_choice_time_ms() +
phase_times()->non_young_free_cset_time_ms();
_non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms /
(double) old_cset_region_length());
......@@ -1133,7 +1134,8 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
// Note that _mmu_tracker->max_gc_time() returns the time in seconds.
double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms);
adjust_concurrent_refinement(phase_times()->average_last_update_rs_time(),
phase_times()->sum_last_update_rs_processed_buffers(), update_rs_time_goal_ms);
_collectionSetChooser->verify();
}
......@@ -1144,7 +1146,11 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
proper_unit_for_byte_size((bytes))
void G1CollectorPolicy::print_heap_transition() {
if (G1Log::finer()) {
_g1->print_size_transition(gclog_or_tty,
_cur_collection_pause_used_at_start_bytes, _g1->used(), _g1->capacity());
}
void G1CollectorPolicy::print_detailed_heap_transition() {
YoungList* young_list = _g1->young_list();
size_t eden_bytes = young_list->eden_used_bytes();
size_t survivor_bytes = young_list->survivor_used_bytes();
......@@ -1171,11 +1177,6 @@ void G1CollectorPolicy::print_heap_transition() {
EXT_SIZE_PARAMS(capacity));
_prev_eden_capacity = eden_capacity;
} else if (G1Log::fine()) {
_g1->print_size_transition(gclog_or_tty,
_cur_collection_pause_used_at_start_bytes,
_g1->used(), _g1->capacity());
}
}
void G1CollectorPolicy::adjust_concurrent_refinement(double update_rs_time,
......@@ -1900,8 +1901,7 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
double young_end_time_sec = os::elapsedTime();
phase_times()->_recorded_young_cset_choice_time_ms =
(young_end_time_sec - young_start_time_sec) * 1000.0;
phase_times()->record_young_cset_choice_time_ms((young_end_time_sec - young_start_time_sec) * 1000.0);
// Set the start of the non-young choice time.
double non_young_start_time_sec = young_end_time_sec;
......@@ -2015,8 +2015,7 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
predicted_pause_time_ms, target_pause_time_ms);
double non_young_end_time_sec = os::elapsedTime();
phase_times()->_recorded_non_young_cset_choice_time_ms =
(non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
phase_times()->record_non_young_cset_choice_time_ms((non_young_end_time_sec - non_young_start_time_sec) * 1000.0);
}
void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) {
......@@ -2035,25 +2034,25 @@ void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTim
if(TraceGen0Time) {
_total.add(pause_time_ms);
_other.add(pause_time_ms - phase_times->accounted_time_ms());
_root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
_parallel.add(phase_times->_cur_collection_par_time_ms);
_ext_root_scan.add(phase_times->_ext_root_scan_time);
_satb_filtering.add(phase_times->_satb_filtering_time);
_update_rs.add(phase_times->_update_rs_time);
_scan_rs.add(phase_times->_scan_rs_time);
_obj_copy.add(phase_times->_obj_copy_time);
_termination.add(phase_times->_termination_time);
double parallel_known_time = phase_times->_ext_root_scan_time +
phase_times->_satb_filtering_time +
phase_times->_update_rs_time +
phase_times->_scan_rs_time +
phase_times->_obj_copy_time +
+ phase_times->_termination_time;
double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time;
_root_region_scan_wait.add(phase_times->root_region_scan_wait_time_ms());
_parallel.add(phase_times->cur_collection_par_time_ms());
_ext_root_scan.add(phase_times->average_last_ext_root_scan_time());
_satb_filtering.add(phase_times->average_last_satb_filtering_times_ms());
_update_rs.add(phase_times->average_last_update_rs_time());
_scan_rs.add(phase_times->average_last_scan_rs_time());
_obj_copy.add(phase_times->average_last_obj_copy_time());
_termination.add(phase_times->average_last_termination_time());
double parallel_known_time = phase_times->average_last_ext_root_scan_time() +
phase_times->average_last_satb_filtering_times_ms() +
phase_times->average_last_update_rs_time() +
phase_times->average_last_scan_rs_time() +
phase_times->average_last_obj_copy_time() +
+ phase_times->average_last_termination_time();
double parallel_other_time = phase_times->cur_collection_par_time_ms() - parallel_known_time;
_parallel_other.add(parallel_other_time);
_clear_ct.add(phase_times->_cur_clear_ct_time_ms);
_clear_ct.add(phase_times->cur_clear_ct_time_ms());
}
}
......
......@@ -683,6 +683,7 @@ public:
void record_collection_pause_end(double pause_time);
void print_heap_transition();
void print_detailed_heap_transition();
// Record the fact that a full collection occurred.
void record_full_collection_start();
......
......@@ -79,194 +79,153 @@ public:
}
};
G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
_max_gc_threads(max_gc_threads),
_min_clear_cc_time_ms(-1.0),
_max_clear_cc_time_ms(-1.0),
_cur_clear_cc_time_ms(0.0),
_cum_clear_cc_time_ms(0.0),
_num_cc_clears(0L)
{
assert(max_gc_threads > 0, "Must have some GC threads");
_par_last_gc_worker_start_times_ms = new double[_max_gc_threads];
_par_last_ext_root_scan_times_ms = new double[_max_gc_threads];
_par_last_satb_filtering_times_ms = new double[_max_gc_threads];
_par_last_update_rs_times_ms = new double[_max_gc_threads];
_par_last_update_rs_processed_buffers = new double[_max_gc_threads];
_par_last_scan_rs_times_ms = new double[_max_gc_threads];
_par_last_obj_copy_times_ms = new double[_max_gc_threads];
_par_last_termination_times_ms = new double[_max_gc_threads];
_par_last_termination_attempts = new double[_max_gc_threads];
_par_last_gc_worker_end_times_ms = new double[_max_gc_threads];
_par_last_gc_worker_times_ms = new double[_max_gc_threads];
_par_last_gc_worker_other_times_ms = new double[_max_gc_threads];
}
void G1GCPhaseTimes::note_gc_start(double pause_start_time_sec, uint active_gc_threads,
bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause) {
assert(active_gc_threads > 0, "The number of threads must be > 0");
assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
_active_gc_threads = active_gc_threads;
_pause_start_time_sec = pause_start_time_sec;
_is_young_gc = is_young_gc;
_is_initial_mark_gc = is_initial_mark_gc;
_gc_cause = gc_cause;
#ifdef ASSERT
// initialise the timing data to something well known so that we can spot
// if something is not set properly
for (uint i = 0; i < _max_gc_threads; ++i) {
_par_last_gc_worker_start_times_ms[i] = -1234.0;
_par_last_ext_root_scan_times_ms[i] = -1234.0;
_par_last_satb_filtering_times_ms[i] = -1234.0;
_par_last_update_rs_times_ms[i] = -1234.0;
_par_last_update_rs_processed_buffers[i] = -1234.0;
_par_last_scan_rs_times_ms[i] = -1234.0;
_par_last_obj_copy_times_ms[i] = -1234.0;
_par_last_termination_times_ms[i] = -1234.0;
_par_last_termination_attempts[i] = -1234.0;
_par_last_gc_worker_end_times_ms[i] = -1234.0;
_par_last_gc_worker_times_ms[i] = -1234.0;
_par_last_gc_worker_other_times_ms[i] = -1234.0;
}
#endif
}
void G1GCPhaseTimes::note_gc_end(double pause_end_time_sec) {
if (G1Log::fine()) {
double pause_time_ms = (pause_end_time_sec - _pause_start_time_sec) * MILLIUNITS;
for (uint i = 0; i < _active_gc_threads; i++) {
_par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
_par_last_gc_worker_start_times_ms[i];
double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
_par_last_satb_filtering_times_ms[i] +
_par_last_update_rs_times_ms[i] +
_par_last_scan_rs_times_ms[i] +
_par_last_obj_copy_times_ms[i] +
_par_last_termination_times_ms[i];
_par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
worker_known_time;
}
print(pause_time_ms);
template <class T>
void WorkerDataArray<T>::print(int level, const char* title) {
if (_length == 1) {
// No need for min, max, average and sum for only one worker
LineBuffer buf(level);
buf.append("[%s: ", title);
buf.append(_print_format, _data[0]);
buf.append_and_print_cr("]");
return;
}
}
T min = _data[0];
T max = _data[0];
T sum = 0;
void G1GCPhaseTimes::print_par_stats(int level,
const char* str,
double* data,
bool showDecimals) {
double min = data[0], max = data[0];
double total = 0.0;
LineBuffer buf(level);
buf.append("[%s (ms):", str);
for (uint i = 0; i < _active_gc_threads; ++i) {
double val = data[i];
if (val < min)
min = val;
if (val > max)
max = val;
total += val;
buf.append("[%s:", title);
for (uint i = 0; i < _length; ++i) {
T val = _data[i];
min = MIN2(val, min);
max = MAX2(val, max);
sum += val;
if (G1Log::finest()) {
if (showDecimals) {
buf.append(" %.1lf", val);
} else {
buf.append(" %d", (int)val);
}
buf.append(" ");
buf.append(_print_format, val);
}
}
if (G1Log::finest()) {
buf.append_and_print_cr("");
}
double avg = total / (double) _active_gc_threads;
if (showDecimals) {
buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
min, avg, max, max - min, total);
} else {
buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
(int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
double avg = (double)sum / (double)_length;
buf.append(" Min: ");
buf.append(_print_format, min);
buf.append(", Avg: ");
buf.append("%.1lf", avg); // Always print average as a double
buf.append(", Max: ");
buf.append(_print_format, max);
buf.append(", Diff: ");
buf.append(_print_format, max - min);
if (_print_sum) {
// for things like the start and end times the sum is not
// that relevant
buf.append(", Sum: ");
buf.append(_print_format, sum);
}
buf.append_and_print_cr("]");
}
void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
}
#ifdef ASSERT
void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int workers) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
template <class T>
void WorkerDataArray<T>::reset() {
for (uint i = 0; i < _length; i++) {
_data[i] = (T)-1;
}
}
void G1GCPhaseTimes::print_stats(int level, const char* str, int value) {
LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
template <class T>
void WorkerDataArray<T>::verify() {
for (uint i = 0; i < _length; i++) {
assert(_data[i] >= (T)0, err_msg("Invalid data for worker %d", i));
}
}
double G1GCPhaseTimes::avg_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = 0.0;
for (uint i = 0; i < _active_gc_threads; ++i) {
ret += data[i];
}
return ret / (double) _active_gc_threads;
} else {
return data[0];
}
#endif
G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
_max_gc_threads(max_gc_threads),
_min_clear_cc_time_ms(-1.0),
_max_clear_cc_time_ms(-1.0),
_cur_clear_cc_time_ms(0.0),
_cum_clear_cc_time_ms(0.0),
_num_cc_clears(0L),
_last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
_last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
_last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
_last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
_last_update_rs_processed_buffers(_max_gc_threads, "%d"),
_last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
_last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
_last_termination_times_ms(_max_gc_threads, "%.1lf"),
_last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
_last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
_last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
_last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf")
{
assert(max_gc_threads > 0, "Must have some GC threads");
}
double G1GCPhaseTimes::max_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = data[0];
for (uint i = 1; i < _active_gc_threads; ++i) {
if (data[i] > ret) {
ret = data[i];
}
}
return ret;
} else {
return data[0];
}
void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
assert(active_gc_threads > 0, "The number of threads must be > 0");
assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
_active_gc_threads = active_gc_threads;
_last_gc_worker_start_times_ms.reset();
_last_ext_root_scan_times_ms.reset();
_last_satb_filtering_times_ms.reset();
_last_update_rs_times_ms.reset();
_last_update_rs_processed_buffers.reset();
_last_scan_rs_times_ms.reset();
_last_obj_copy_times_ms.reset();
_last_termination_times_ms.reset();
_last_termination_attempts.reset();
_last_gc_worker_end_times_ms.reset();
_last_gc_worker_times_ms.reset();
_last_gc_worker_other_times_ms.reset();
}
double G1GCPhaseTimes::sum_of_values(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double sum = 0.0;
void G1GCPhaseTimes::note_gc_end() {
_last_gc_worker_start_times_ms.verify();
_last_ext_root_scan_times_ms.verify();
_last_satb_filtering_times_ms.verify();
_last_update_rs_times_ms.verify();
_last_update_rs_processed_buffers.verify();
_last_scan_rs_times_ms.verify();
_last_obj_copy_times_ms.verify();
_last_termination_times_ms.verify();
_last_termination_attempts.verify();
_last_gc_worker_end_times_ms.verify();
for (uint i = 0; i < _active_gc_threads; i++) {
sum += data[i];
double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i);
_last_gc_worker_times_ms.set(i, worker_time);
double worker_known_time = _last_ext_root_scan_times_ms.get(i) +
_last_satb_filtering_times_ms.get(i) +
_last_update_rs_times_ms.get(i) +
_last_scan_rs_times_ms.get(i) +
_last_obj_copy_times_ms.get(i) +
_last_termination_times_ms.get(i);
double worker_other_time = worker_time - worker_known_time;
_last_gc_worker_other_times_ms.set(i, worker_other_time);
}
return sum;
} else {
return data[0];
}
}
double G1GCPhaseTimes::max_sum(double* data1, double* data2) {
double ret = data1[0] + data2[0];
_last_gc_worker_times_ms.verify();
_last_gc_worker_other_times_ms.verify();
}
if (G1CollectedHeap::use_parallel_gc_threads()) {
for (uint i = 1; i < _active_gc_threads; ++i) {
double data = data1[i] + data2[i];
if (data > ret) {
ret = data;
}
}
}
return ret;
void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
}
void G1GCPhaseTimes::collapse_par_times() {
_ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
_satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
_update_rs_time = avg_value(_par_last_update_rs_times_ms);
_update_rs_processed_buffers =
sum_of_values(_par_last_update_rs_processed_buffers);
_scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
_obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
_termination_time = avg_value(_par_last_termination_times_ms);
void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int workers) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
}
double G1GCPhaseTimes::accounted_time_ms() {
......@@ -286,58 +245,37 @@ double G1GCPhaseTimes::accounted_time_ms() {
return misc_time_ms;
}
void G1GCPhaseTimes::print(double pause_time_ms) {
if (PrintGCTimeStamps) {
gclog_or_tty->stamp();
gclog_or_tty->print(": ");
}
GCCauseString gc_cause_str = GCCauseString("GC pause", _gc_cause)
.append(_is_young_gc ? " (young)" : " (mixed)")
.append(_is_initial_mark_gc ? " (initial-mark)" : "");
gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_ms / 1000.0);
if (!G1Log::finer()) {
return;
}
void G1GCPhaseTimes::print(double pause_time_sec) {
if (_root_region_scan_wait_time_ms > 0.0) {
print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
if (G1CollectedHeap::use_parallel_gc_threads()) {
print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
if (_satb_filtering_time > 0.0) {
print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
}
print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
if (G1Log::finest()) {
print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
false /* showDecimals */);
_last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)");
_last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)");
if (_last_satb_filtering_times_ms.sum() > 0.0) {
_last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)");
}
print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
print_par_stats(2, "Termination", _par_last_termination_times_ms);
_last_update_rs_times_ms.print(2, "Update RS (ms)");
_last_update_rs_processed_buffers.print(3, "Processed Buffers");
_last_scan_rs_times_ms.print(2, "Scan RS (ms)");
_last_obj_copy_times_ms.print(2, "Object Copy (ms)");
_last_termination_times_ms.print(2, "Termination (ms)");
if (G1Log::finest()) {
print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
false /* showDecimals */);
_last_termination_attempts.print(3, "Termination Attempts");
}
print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms);
print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
_last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)");
_last_gc_worker_times_ms.print(2, "GC Worker Total (ms)");
_last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)");
} else {
print_stats(1, "Ext Root Scanning", _ext_root_scan_time);
if (_satb_filtering_time > 0.0) {
print_stats(1, "SATB Filtering", _satb_filtering_time);
}
print_stats(1, "Update RS", _update_rs_time);
if (G1Log::finest()) {
print_stats(2, "Processed Buffers", (int)_update_rs_processed_buffers);
_last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)");
if (_last_satb_filtering_times_ms.sum() > 0.0) {
_last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)");
}
print_stats(1, "Scan RS", _scan_rs_time);
print_stats(1, "Object Copying", _obj_copy_time);
_last_update_rs_times_ms.print(1, "Update RS (ms)");
_last_update_rs_processed_buffers.print(2, "Processed Buffers");
_last_scan_rs_times_ms.print(1, "Scan RS (ms)");
_last_obj_copy_times_ms.print(1, "Object Copy (ms)");
}
print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
......@@ -350,8 +288,11 @@ void G1GCPhaseTimes::print(double pause_time_ms) {
print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
}
}
double misc_time_ms = pause_time_ms - accounted_time_ms();
double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
print_stats(1, "Other", misc_time_ms);
if (_cur_verify_before_time_ms > 0.0) {
print_stats(2, "Verify Before", _cur_verify_before_time_ms);
}
print_stats(2, "Choose CSet",
(_recorded_young_cset_choice_time_ms +
_recorded_non_young_cset_choice_time_ms));
......@@ -360,6 +301,9 @@ void G1GCPhaseTimes::print(double pause_time_ms) {
print_stats(2, "Free CSet",
(_recorded_young_free_cset_time_ms +
_recorded_non_young_free_cset_time_ms));
if (_cur_verify_after_time_ms > 0.0) {
print_stats(2, "Verify After", _cur_verify_after_time_ms);
}
}
void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) {
......
......@@ -28,52 +28,109 @@
#include "memory/allocation.hpp"
#include "gc_interface/gcCause.hpp"
template <class T>
class WorkerDataArray : public CHeapObj<mtGC> {
T* _data;
uint _length;
const char* _print_format;
bool _print_sum;
// We are caching the sum and average to only have to calculate them once.
// This is not done in an MT-safe way. It is intetened to allow single
// threaded code to call sum() and average() multiple times in any order
// without having to worry about the cost.
bool _has_new_data;
T _sum;
double _average;
public:
WorkerDataArray(uint length, const char* print_format, bool print_sum = true) :
_length(length), _print_format(print_format), _print_sum(print_sum), _has_new_data(true) {
assert(length > 0, "Must have some workers to store data for");
_data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
}
~WorkerDataArray() {
FREE_C_HEAP_ARRAY(T, _data, mtGC);
}
void set(uint worker_i, T value) {
assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
assert(_data[worker_i] == (T)-1, err_msg("Overwriting data for worker %d", worker_i));
_data[worker_i] = value;
_has_new_data = true;
}
T get(uint worker_i) {
assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
assert(_data[worker_i] != (T)-1, err_msg("No data to add to for worker %d", worker_i));
return _data[worker_i];
}
void add(uint worker_i, T value) {
assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
assert(_data[worker_i] != (T)-1, err_msg("No data to add to for worker %d", worker_i));
_data[worker_i] += value;
_has_new_data = true;
}
double average(){
if (_has_new_data) {
calculate_totals();
}
return _average;
}
T sum() {
if (_has_new_data) {
calculate_totals();
}
return _sum;
}
void print(int level, const char* title);
void reset() PRODUCT_RETURN;
void verify() PRODUCT_RETURN;
private:
void calculate_totals(){
_sum = (T)0;
for (uint i = 0; i < _length; ++i) {
_sum += _data[i];
}
_average = (double)_sum / (double)_length;
_has_new_data = false;
}
};
class G1GCPhaseTimes : public CHeapObj<mtGC> {
friend class G1CollectorPolicy;
friend class TraceGen0TimeData;
private:
uint _active_gc_threads;
uint _max_gc_threads;
GCCause::Cause _gc_cause;
bool _is_young_gc;
bool _is_initial_mark_gc;
double _pause_start_time_sec;
double* _par_last_gc_worker_start_times_ms;
double* _par_last_ext_root_scan_times_ms;
double* _par_last_satb_filtering_times_ms;
double* _par_last_update_rs_times_ms;
double* _par_last_update_rs_processed_buffers;
double* _par_last_scan_rs_times_ms;
double* _par_last_obj_copy_times_ms;
double* _par_last_termination_times_ms;
double* _par_last_termination_attempts;
double* _par_last_gc_worker_end_times_ms;
double* _par_last_gc_worker_times_ms;
double* _par_last_gc_worker_other_times_ms;
WorkerDataArray<double> _last_gc_worker_start_times_ms;
WorkerDataArray<double> _last_ext_root_scan_times_ms;
WorkerDataArray<double> _last_satb_filtering_times_ms;
WorkerDataArray<double> _last_update_rs_times_ms;
WorkerDataArray<int> _last_update_rs_processed_buffers;
WorkerDataArray<double> _last_scan_rs_times_ms;
WorkerDataArray<double> _last_obj_copy_times_ms;
WorkerDataArray<double> _last_termination_times_ms;
WorkerDataArray<size_t> _last_termination_attempts;
WorkerDataArray<double> _last_gc_worker_end_times_ms;
WorkerDataArray<double> _last_gc_worker_times_ms;
WorkerDataArray<double> _last_gc_worker_other_times_ms;
double _cur_collection_par_time_ms;
double _cur_collection_code_root_fixup_time_ms;
double _cur_clear_ct_time_ms;
double _cur_ref_proc_time_ms;
double _cur_ref_enq_time_ms;
// Helper methods for detailed logging
void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
void print_stats(int level, const char* str, double value);
void print_stats(int level, const char* str, double value, int workers);
void print_stats(int level, const char* str, int value);
double avg_value(double* data);
double max_value(double* data);
double sum_of_values(double* data);
double max_sum(double* data1, double* data2);
double accounted_time_ms();
// Card Table Count Cache stats
double _min_clear_cc_time_ms; // min
double _max_clear_cc_time_ms; // max
......@@ -81,19 +138,6 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
double _cum_clear_cc_time_ms; // cummulative clearing time
jlong _num_cc_clears; // number of times the card count cache has been cleared
// The following insance variables are directly accessed by G1CollectorPolicy
// and TraceGen0TimeData. This is why those classes are declared friends.
// An alternative is to add getters and setters for all of these fields.
// It might also be possible to restructure the code to reduce these
// dependencies.
double _ext_root_scan_time;
double _satb_filtering_time;
double _update_rs_time;
double _update_rs_processed_buffers;
double _scan_rs_time;
double _obj_copy_time;
double _termination_time;
double _cur_collection_start_sec;
double _root_region_scan_wait_time_ms;
......@@ -103,79 +147,58 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
double _recorded_young_free_cset_time_ms;
double _recorded_non_young_free_cset_time_ms;
void print(double pause_time_ms);
double _cur_verify_before_time_ms;
double _cur_verify_after_time_ms;
// Helper methods for detailed logging
void print_stats(int level, const char* str, double value);
void print_stats(int level, const char* str, double value, int workers);
public:
G1GCPhaseTimes(uint max_gc_threads);
void note_gc_start(double pause_start_time_sec, uint active_gc_threads,
bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause);
void note_gc_end(double pause_end_time_sec);
void collapse_par_times();
void note_gc_start(uint active_gc_threads);
void note_gc_end();
void print(double pause_time_sec);
void record_gc_worker_start_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_gc_worker_start_times_ms[worker_i] = ms;
_last_gc_worker_start_times_ms.set(worker_i, ms);
}
void record_ext_root_scan_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_ext_root_scan_times_ms[worker_i] = ms;
_last_ext_root_scan_times_ms.set(worker_i, ms);
}
void record_satb_filtering_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_satb_filtering_times_ms[worker_i] = ms;
_last_satb_filtering_times_ms.set(worker_i, ms);
}
void record_update_rs_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_update_rs_times_ms[worker_i] = ms;
_last_update_rs_times_ms.set(worker_i, ms);
}
void record_update_rs_processed_buffers (uint worker_i,
double processed_buffers) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_update_rs_processed_buffers[worker_i] = processed_buffers;
void record_update_rs_processed_buffers(uint worker_i, int processed_buffers) {
_last_update_rs_processed_buffers.set(worker_i, processed_buffers);
}
void record_scan_rs_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_scan_rs_times_ms[worker_i] = ms;
}
void reset_obj_copy_time(uint worker_i) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_obj_copy_times_ms[worker_i] = 0.0;
_last_scan_rs_times_ms.set(worker_i, ms);
}
void reset_obj_copy_time() {
reset_obj_copy_time(0);
void record_obj_copy_time(uint worker_i, double ms) {
_last_obj_copy_times_ms.set(worker_i, ms);
}
void record_obj_copy_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_obj_copy_times_ms[worker_i] += ms;
void add_obj_copy_time(uint worker_i, double ms) {
_last_obj_copy_times_ms.add(worker_i, ms);
}
void record_termination(uint worker_i, double ms, size_t attempts) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_termination_times_ms[worker_i] = ms;
_par_last_termination_attempts[worker_i] = (double) attempts;
_last_termination_times_ms.set(worker_i, ms);
_last_termination_attempts.set(worker_i, attempts);
}
void record_gc_worker_end_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_gc_worker_end_times_ms[worker_i] = ms;
_last_gc_worker_end_times_ms.set(worker_i, ms);
}
void record_clear_ct_time(double ms) {
......@@ -211,6 +234,88 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
void record_non_young_free_cset_time_ms(double time_ms) {
_recorded_non_young_free_cset_time_ms = time_ms;
}
void record_young_cset_choice_time_ms(double time_ms) {
_recorded_young_cset_choice_time_ms = time_ms;
}
void record_non_young_cset_choice_time_ms(double time_ms) {
_recorded_non_young_cset_choice_time_ms = time_ms;
}
void record_cur_collection_start_sec(double time_ms) {
_cur_collection_start_sec = time_ms;
}
void record_verify_before_time_ms(double time_ms) {
_cur_verify_before_time_ms = time_ms;
}
void record_verify_after_time_ms(double time_ms) {
_cur_verify_after_time_ms = time_ms;
}
double accounted_time_ms();
double cur_collection_start_sec() {
return _cur_collection_start_sec;
}
double cur_collection_par_time_ms() {
return _cur_collection_par_time_ms;
}
double cur_clear_ct_time_ms() {
return _cur_clear_ct_time_ms;
}
double root_region_scan_wait_time_ms() {
return _root_region_scan_wait_time_ms;
}
double young_cset_choice_time_ms() {
return _recorded_young_cset_choice_time_ms;
}
double young_free_cset_time_ms() {
return _recorded_young_free_cset_time_ms;
}
double non_young_cset_choice_time_ms() {
return _recorded_non_young_cset_choice_time_ms;
}
double non_young_free_cset_time_ms() {
return _recorded_non_young_free_cset_time_ms;
}
double average_last_update_rs_time() {
return _last_update_rs_times_ms.average();
}
int sum_last_update_rs_processed_buffers() {
return _last_update_rs_processed_buffers.sum();
}
double average_last_scan_rs_time(){
return _last_scan_rs_times_ms.average();
}
double average_last_obj_copy_time() {
return _last_obj_copy_times_ms.average();
}
double average_last_termination_time() {
return _last_termination_times_ms.average();
}
double average_last_ext_root_scan_time() {
return _last_ext_root_scan_times_ms.average();
}
double average_last_satb_filtering_times_ms() {
return _last_satb_filtering_times_ms.average();
}
};
#endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
......@@ -324,7 +324,7 @@ void G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
if (G1UseParallelRSetUpdating || (worker_i == 0)) {
updateRS(&into_cset_dcq, worker_i);
} else {
_g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0.0);
_g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0);
_g1p->phase_times()->record_update_rs_time(worker_i, 0.0);
}
if (G1UseParallelRSetScanning || (worker_i == 0)) {
......
......@@ -311,7 +311,35 @@
"as a percentage of the heap size.") \
\
experimental(ccstr, G1LogLevel, NULL, \
"Log level for G1 logging: fine, finer, finest")
"Log level for G1 logging: fine, finer, finest") \
\
notproduct(bool, G1EvacuationFailureALot, false, \
"Force use of evacuation failure handling during certain " \
"evacuation pauses") \
\
develop(uintx, G1EvacuationFailureALotCount, 1000, \
"Number of successful evacuations between evacuation failures " \
"occurring at object copying") \
\
develop(uintx, G1EvacuationFailureALotInterval, 5, \
"Total collections between forced triggering of evacuation " \
"failures") \
\
develop(bool, G1EvacuationFailureALotDuringConcMark, true, \
"Force use of evacuation failure handling during evacuation " \
"pauses when marking is in progress") \
\
develop(bool, G1EvacuationFailureALotDuringInitialMark, true, \
"Force use of evacuation failure handling during initial mark " \
"evacuation pauses") \
\
develop(bool, G1EvacuationFailureALotDuringYoungGC, true, \
"Force use of evacuation failure handling during young " \
"evacuation pauses") \
\
develop(bool, G1EvacuationFailureALotDuringMixedGC, true, \
"Force use of evacuation failure handling during mixed " \
"evacuation pauses")
G1_FLAGS(DECLARE_DEVELOPER_FLAG, DECLARE_PD_DEVELOPER_FLAG, DECLARE_PRODUCT_FLAG, DECLARE_PD_PRODUCT_FLAG, DECLARE_DIAGNOSTIC_FLAG, DECLARE_EXPERIMENTAL_FLAG, DECLARE_NOTPRODUCT_FLAG, DECLARE_MANAGEABLE_FLAG, DECLARE_PRODUCT_RW_FLAG)
......
......@@ -1916,7 +1916,7 @@ bool Arguments::check_vm_args_consistency() {
(ExplicitGCInvokesConcurrent ||
ExplicitGCInvokesConcurrentAndUnloadsClasses)) {
jio_fprintf(defaultStream::error_stream(),
"error: +ExplictGCInvokesConcurrent[AndUnloadsClasses] conflicts"
"error: +ExplicitGCInvokesConcurrent[AndUnloadsClasses] conflicts"
" with -UseAsyncConcMarkSweepGC");
status = false;
}
......
Markdown is supported
0% .
You are about to add 0 people to the discussion. Proceed with caution.
先完成此消息的编辑!
想要评论请 注册