Mercurial > hg > graal-compiler
changeset 6637:4d318b1e73ca
Merge
author | twisti |
---|---|
date | Fri, 31 Aug 2012 10:48:08 -0700 |
parents | 220b59f8413f (diff) 0acd345fd810 (current diff) |
children | 1eb74cd5994b |
files | |
diffstat | 13 files changed, 640 insertions(+), 403 deletions(-) [+] |
line wrap: on
line diff
--- a/src/os/bsd/vm/os_bsd.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/os/bsd/vm/os_bsd.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/os/linux/vm/os_linux.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/os/linux/vm/os_linux.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/os/posix/launcher/launcher.script Wed Aug 29 13:02:40 2012 -0700 +++ b/src/os/posix/launcher/launcher.script Fri Aug 31 10:48:08 2012 -0700 @@ -29,7 +29,7 @@ # inside Emacs". # # If the first parameter is "-dbx", HotSpot will be launched inside dbx. -# +# # If the first parameter is "-valgrind", HotSpot will be launched # inside Valgrind (http://valgrind.kde.org) using the Memcheck skin, # and with memory leak detection enabled. This currently (2005jan19) @@ -45,19 +45,19 @@ # This is the name of the gdb binary to use if [ ! "$GDB" ] -then +then GDB=gdb fi # This is the name of the gdb binary to use if [ ! "$DBX" ] -then +then DBX=dbx fi # This is the name of the Valgrind binary to use if [ ! "$VALGRIND" ] -then +then VALGRIND=valgrind fi @@ -98,7 +98,7 @@ JDK= if [ "${ALT_JAVA_HOME}" = "" ]; then . ${MYDIR}/jdkpath.sh -else +else JDK=${ALT_JAVA_HOME%%/jre}; fi @@ -114,22 +114,34 @@ # any. JRE=$JDK/jre JAVA_HOME=$JDK +export JAVA_HOME + ARCH=@@LIBARCH@@ - SBP=${MYDIR}:${JRE}/lib/${ARCH} -# Set up a suitable LD_LIBRARY_PATH -if [ -z "$LD_LIBRARY_PATH" ] +# Set up a suitable LD_LIBRARY_PATH or DYLD_LIBRARY_PATH +OS=`uname -s` +if [ "${OS}" = "Darwin" ] then - LD_LIBRARY_PATH="$SBP" + if [ -z "$DYLD_LIBRARY_PATH" ] + then + DYLD_LIBRARY_PATH="$SBP" + else + DYLD_LIBRARY_PATH="$SBP:$DYLD_LIBRARY_PATH" + fi + export DYLD_LIBRARY_PATH else - LD_LIBRARY_PATH="$SBP:$LD_LIBRARY_PATH" + # not 'Darwin' + if [ -z "$LD_LIBRARY_PATH" ] + then + LD_LIBRARY_PATH="$SBP" + else + LD_LIBRARY_PATH="$SBP:$LD_LIBRARY_PATH" + fi + export LD_LIBRARY_PATH fi -export LD_LIBRARY_PATH -export JAVA_HOME - JPARMS="$@ $JAVA_ARGS"; # Locate the gamma development launcher
--- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1CollectedHeap.inline.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.inline.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1RemSet.cpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1RemSet.cpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/gc_implementation/g1/g1_globals.hpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/gc_implementation/g1/g1_globals.hpp Fri Aug 31 10:48:08 2012 -0700 @@ -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/src/share/vm/runtime/arguments.cpp Wed Aug 29 13:02:40 2012 -0700 +++ b/src/share/vm/runtime/arguments.cpp Fri Aug 31 10:48:08 2012 -0700 @@ -1916,7 +1916,7 @@ (ExplicitGCInvokesConcurrent || ExplicitGCInvokesConcurrentAndUnloadsClasses)) { jio_fprintf(defaultStream::error_stream(), - "error: +ExplictGCInvokesConcurrent[AndUnloadsClasses] conflicts" + "error: +ExplicitGCInvokesConcurrent[AndUnloadsClasses] conflicts" " with -UseAsyncConcMarkSweepGC"); status = false; }