--- a/hotspot/src/os/bsd/vm/os_bsd.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/os/bsd/vm/os_bsd.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -1,5 +1,5 @@
/*
- * 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 @@
static void fast_thread_clock_init(void);
#endif
- static bool supports_monotonic_clock() {
+ static inline bool supports_monotonic_clock() {
return _clock_gettime != NULL;
}
--- a/hotspot/src/os/linux/vm/os_linux.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/os/linux/vm/os_linux.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -1,5 +1,5 @@
/*
- * 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 @@
// 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;
}
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Fri Aug 31 08:30:30 2012 +0200
@@ -1246,6 +1246,31 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
gc_epilogue(false);
- g1_policy()->phase_times()->note_gc_end(os::elapsedTime());
-
- // We have to do this after we decide whether to expand the heap or not.
+ 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)" : "");
+
+ 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 @@
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 @@
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 @@
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 @@
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 @@
_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 @@
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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -405,6 +405,10 @@
// 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 @@
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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.inline.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.inline.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -1,5 +1,5 @@
/*
- * 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 @@
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 @@
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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Fri Aug 31 08:30:30 2012 +0200
@@ -795,7 +795,7 @@
_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 @@
_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 @@
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 @@
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 @@
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 @@
}
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 @@
// 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 @@
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 @@
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 @@
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 @@
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 @@
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);
+ _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->_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_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;
+ 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());
}
}
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -683,6 +683,7 @@
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();
--- a/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Fri Aug 31 08:30:30 2012 +0200
@@ -79,119 +79,145 @@
}
};
+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;
+
+ LineBuffer buf(level);
+ 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()) {
+ buf.append(" ");
+ buf.append(_print_format, val);
+ }
+ }
+
+ if (G1Log::finest()) {
+ buf.append_and_print_cr("");
+ }
+
+ 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("]");
+}
+
+#ifdef ASSERT
+
+template <class T>
+void WorkerDataArray<T>::reset() {
+ for (uint i = 0; i < _length; i++) {
+ _data[i] = (T)-1;
+ }
+}
+
+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));
+ }
+}
+
+#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)
+ _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");
- _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) {
+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;
- _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
+ _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();
}
-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;
+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++) {
- _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_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 = _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];
+ 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);
- _par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
- worker_known_time;
+ double worker_other_time = worker_time - worker_known_time;
+ _last_gc_worker_other_times_ms.set(i, worker_other_time);
}
- print(pause_time_ms);
- }
-
-}
-
-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;
- if (G1Log::finest()) {
- if (showDecimals) {
- buf.append(" %.1lf", val);
- } else {
- buf.append(" %d", (int)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);
- }
+ _last_gc_worker_times_ms.verify();
+ _last_gc_worker_other_times_ms.verify();
}
void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
@@ -202,73 +228,6 @@
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
}
-void G1GCPhaseTimes::print_stats(int level, const char* str, int value) {
- LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
-}
-
-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];
- }
-}
-
-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];
- }
-}
-
-double G1GCPhaseTimes::sum_of_values(double* data) {
- if (G1CollectedHeap::use_parallel_gc_threads()) {
- double sum = 0.0;
- for (uint i = 0; i < _active_gc_threads; i++) {
- sum += data[i];
- }
- return sum;
- } else {
- return data[0];
- }
-}
-
-double G1GCPhaseTimes::max_sum(double* data1, double* data2) {
- double ret = data1[0] + data2[0];
-
- 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::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);
-}
-
double G1GCPhaseTimes::accounted_time_ms() {
// Subtract the root region scanning wait time. It's initialized to
// zero at the start of the pause.
@@ -286,58 +245,37 @@
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);
+ _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, "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 */);
- }
- 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);
+ _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, "Update RS", _update_rs_time);
- if (G1Log::finest()) {
- print_stats(2, "Processed Buffers", (int)_update_rs_processed_buffers);
- }
- 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 @@
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 @@
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) {
--- a/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -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 @@
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 @@
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;
- }
-
- void reset_obj_copy_time() {
- reset_obj_copy_time(0);
+ _last_scan_rs_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;
+ _last_obj_copy_times_ms.set(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 @@
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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp Fri Aug 31 08:30:30 2012 +0200
@@ -324,7 +324,7 @@
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)) {
--- a/hotspot/src/share/vm/gc_implementation/g1/g1_globals.hpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1_globals.hpp Fri Aug 31 08:30:30 2012 +0200
@@ -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)
--- a/hotspot/src/share/vm/runtime/arguments.cpp Fri Aug 24 19:45:42 2012 -0700
+++ b/hotspot/src/share/vm/runtime/arguments.cpp Fri Aug 31 08:30:30 2012 +0200
@@ -1916,7 +1916,7 @@
(ExplicitGCInvokesConcurrent ||
ExplicitGCInvokesConcurrentAndUnloadsClasses)) {
jio_fprintf(defaultStream::error_stream(),
- "error: +ExplictGCInvokesConcurrent[AndUnloadsClasses] conflicts"
+ "error: +ExplicitGCInvokesConcurrent[AndUnloadsClasses] conflicts"
" with -UseAsyncConcMarkSweepGC");
status = false;
}