# HG changeset patch # User tonyp # Date 1246990980 14400 # Node ID 0316eac49d5aa9dfe67c700e7aab04e46de58ade # Parent e7d5557ad624b93ca6eba3b9e7b2fea53060368f 6855834: G1: minimize the output when -XX:+PrintHeapAtGC is set Summary: Changing the behavior of -XX:+PrintHeapAtGC for G1 from printing lengthy, per-region information to instead printing a concise summary. Reviewed-by: ysr, apetrusenko, jcoomes diff -r e7d5557ad624 -r 0316eac49d5a src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Thu Jul 02 16:28:15 2009 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Tue Jul 07 14:23:00 2009 -0400 @@ -902,6 +902,10 @@ size_t word_size) { ResourceMark rm; + if (PrintHeapAtGC) { + Universe::print_heap_before_gc(); + } + if (full && DisableExplicitGC) { gclog_or_tty->print("\n\n\nDisabling Explicit GC\n\n\n"); return; @@ -927,7 +931,7 @@ g1_policy()->record_full_collection_start(); gc_prologue(true); - increment_total_collections(); + increment_total_collections(true /* full gc */); size_t g1h_prev_used = used(); assert(used() == recalculate_used(), "Should be equal"); @@ -1066,6 +1070,10 @@ assert( check_young_list_empty(false, false), "young list should be empty at this point"); } + + if (PrintHeapAtGC) { + Universe::print_heap_after_gc(); + } } void G1CollectedHeap::do_full_collection(bool clear_all_soft_refs) { @@ -2325,9 +2333,37 @@ } }; -void G1CollectedHeap::print() const { print_on(gclog_or_tty); } +void G1CollectedHeap::print() const { print_on(tty); } void G1CollectedHeap::print_on(outputStream* st) const { + print_on(st, PrintHeapAtGCExtended); +} + +void G1CollectedHeap::print_on(outputStream* st, bool extended) const { + st->print(" %-20s", "garbage-first heap"); + st->print(" total " SIZE_FORMAT "K, used " SIZE_FORMAT "K", + capacity()/K, used()/K); + st->print(" [" INTPTR_FORMAT ", " INTPTR_FORMAT ", " INTPTR_FORMAT ")", + _g1_storage.low_boundary(), + _g1_storage.high(), + _g1_storage.high_boundary()); + st->cr(); + st->print(" region size " SIZE_FORMAT "K, ", + HeapRegion::GrainBytes/K); + size_t young_regions = _young_list->length(); + st->print(SIZE_FORMAT " young (" SIZE_FORMAT "K), ", + young_regions, young_regions * HeapRegion::GrainBytes / K); + size_t survivor_regions = g1_policy()->recorded_survivor_regions(); + st->print(SIZE_FORMAT " survivors (" SIZE_FORMAT "K)", + survivor_regions, survivor_regions * HeapRegion::GrainBytes / K); + st->cr(); + perm()->as_gen()->print_on(st); + if (extended) { + print_on_extended(st); + } +} + +void G1CollectedHeap::print_on_extended(outputStream* st) const { PrintRegionClosure blk(st); _hrs->iterate(&blk); } @@ -2408,10 +2444,6 @@ } void G1CollectedHeap::gc_prologue(bool full /* Ignored */) { - if (PrintHeapAtGC){ - gclog_or_tty->print_cr(" {Heap before GC collections=%d:", total_collections()); - Universe::print(); - } assert(InlineCacheBuffer::is_empty(), "should have cleaned up ICBuffer"); // Call allocation profiler AllocationProfiler::iterate_since_last_gc(); @@ -2425,12 +2457,6 @@ // is set. COMPILER2_PRESENT(assert(DerivedPointerTable::is_empty(), "derived pointer present")); - - if (PrintHeapAtGC){ - gclog_or_tty->print_cr(" Heap after GC collections=%d:", total_collections()); - Universe::print(); - gclog_or_tty->print("} "); - } } void G1CollectedHeap::do_collection_pause() { @@ -2559,241 +2585,250 @@ void G1CollectedHeap::do_collection_pause_at_safepoint() { - char verbose_str[128]; - sprintf(verbose_str, "GC pause "); - if (g1_policy()->in_young_gc_mode()) { - if (g1_policy()->full_young_gcs()) - strcat(verbose_str, "(young)"); - else - strcat(verbose_str, "(partial)"); - } - if (g1_policy()->should_initiate_conc_mark()) - strcat(verbose_str, " (initial-mark)"); - - GCCauseSetter x(this, GCCause::_g1_inc_collection_pause); - - // if PrintGCDetails is on, we'll print long statistics information - // in the collector policy code, so let's not print this as the output - // is messy if we do. - gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); - TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - TraceTime t(verbose_str, PrintGC && !PrintGCDetails, true, gclog_or_tty); - - ResourceMark rm; - assert(SafepointSynchronize::is_at_safepoint(), "should be at safepoint"); - assert(Thread::current() == VMThread::vm_thread(), "should be in vm thread"); - guarantee(!is_gc_active(), "collection is not reentrant"); - assert(regions_accounted_for(), "Region leakage!"); - - increment_gc_time_stamp(); - - if (g1_policy()->in_young_gc_mode()) { - assert(check_young_list_well_formed(), - "young list should be well formed"); - } - - if (GC_locker::is_active()) { - return; // GC is disabled (e.g. JNI GetXXXCritical operation) - } - - bool abandoned = false; - { // Call to jvmpi::post_class_unload_events must occur outside of active GC - IsGCActiveMark x; - - gc_prologue(false); - increment_total_collections(); + if (PrintHeapAtGC) { + Universe::print_heap_before_gc(); + } + + { + char verbose_str[128]; + sprintf(verbose_str, "GC pause "); + if (g1_policy()->in_young_gc_mode()) { + if (g1_policy()->full_young_gcs()) + strcat(verbose_str, "(young)"); + else + strcat(verbose_str, "(partial)"); + } + if (g1_policy()->should_initiate_conc_mark()) + strcat(verbose_str, " (initial-mark)"); + + GCCauseSetter x(this, GCCause::_g1_inc_collection_pause); + + // if PrintGCDetails is on, we'll print long statistics information + // in the collector policy code, so let's not print this as the output + // is messy if we do. + gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); + TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); + TraceTime t(verbose_str, PrintGC && !PrintGCDetails, true, gclog_or_tty); + + ResourceMark rm; + assert(SafepointSynchronize::is_at_safepoint(), "should be at safepoint"); + assert(Thread::current() == VMThread::vm_thread(), "should be in vm thread"); + guarantee(!is_gc_active(), "collection is not reentrant"); + assert(regions_accounted_for(), "Region leakage!"); + + increment_gc_time_stamp(); + + if (g1_policy()->in_young_gc_mode()) { + assert(check_young_list_well_formed(), + "young list should be well formed"); + } + + if (GC_locker::is_active()) { + return; // GC is disabled (e.g. JNI GetXXXCritical operation) + } + + bool abandoned = false; + { // Call to jvmpi::post_class_unload_events must occur outside of active GC + IsGCActiveMark x; + + gc_prologue(false); + increment_total_collections(false /* full gc */); #if G1_REM_SET_LOGGING - gclog_or_tty->print_cr("\nJust chose CS, heap:"); - print(); + gclog_or_tty->print_cr("\nJust chose CS, heap:"); + print(); #endif - if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) { - HandleMark hm; // Discard invalid handles created during verification - prepare_for_verify(); - gclog_or_tty->print(" VerifyBeforeGC:"); - Universe::verify(false); - } - - COMPILER2_PRESENT(DerivedPointerTable::clear()); - - // We want to turn off ref discovery, if necessary, and turn it back on - // on again later if we do. - bool was_enabled = ref_processor()->discovery_enabled(); - if (was_enabled) ref_processor()->disable_discovery(); - - // Forget the current alloc region (we might even choose it to be part - // of the collection set!). - abandon_cur_alloc_region(); - - // The elapsed time induced by the start time below deliberately elides - // the possible verification above. - double start_time_sec = os::elapsedTime(); - GCOverheadReporter::recordSTWStart(start_time_sec); - size_t start_used_bytes = used(); - if (!G1ConcMark) { - do_sync_mark(); - } - - g1_policy()->record_collection_pause_start(start_time_sec, - start_used_bytes); - - guarantee(_in_cset_fast_test == NULL, "invariant"); - guarantee(_in_cset_fast_test_base == NULL, "invariant"); - _in_cset_fast_test_length = max_regions(); - _in_cset_fast_test_base = + if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) { + HandleMark hm; // Discard invalid handles created during verification + prepare_for_verify(); + gclog_or_tty->print(" VerifyBeforeGC:"); + Universe::verify(false); + } + + COMPILER2_PRESENT(DerivedPointerTable::clear()); + + // We want to turn off ref discovery, if necessary, and turn it back on + // on again later if we do. + bool was_enabled = ref_processor()->discovery_enabled(); + if (was_enabled) ref_processor()->disable_discovery(); + + // Forget the current alloc region (we might even choose it to be part + // of the collection set!). + abandon_cur_alloc_region(); + + // The elapsed time induced by the start time below deliberately elides + // the possible verification above. + double start_time_sec = os::elapsedTime(); + GCOverheadReporter::recordSTWStart(start_time_sec); + size_t start_used_bytes = used(); + if (!G1ConcMark) { + do_sync_mark(); + } + + g1_policy()->record_collection_pause_start(start_time_sec, + start_used_bytes); + + guarantee(_in_cset_fast_test == NULL, "invariant"); + guarantee(_in_cset_fast_test_base == NULL, "invariant"); + _in_cset_fast_test_length = max_regions(); + _in_cset_fast_test_base = NEW_C_HEAP_ARRAY(bool, _in_cset_fast_test_length); - memset(_in_cset_fast_test_base, false, + memset(_in_cset_fast_test_base, false, _in_cset_fast_test_length * sizeof(bool)); - // We're biasing _in_cset_fast_test to avoid subtracting the - // beginning of the heap every time we want to index; basically - // it's the same with what we do with the card table. - _in_cset_fast_test = _in_cset_fast_test_base - + // We're biasing _in_cset_fast_test to avoid subtracting the + // beginning of the heap every time we want to index; basically + // it's the same with what we do with the card table. + _in_cset_fast_test = _in_cset_fast_test_base - ((size_t) _g1_reserved.start() >> HeapRegion::LogOfHRGrainBytes); #if SCAN_ONLY_VERBOSE - _young_list->print(); + _young_list->print(); #endif // SCAN_ONLY_VERBOSE - if (g1_policy()->should_initiate_conc_mark()) { - concurrent_mark()->checkpointRootsInitialPre(); - } - save_marks(); - - // We must do this before any possible evacuation that should propagate - // marks. - if (mark_in_progress()) { - double start_time_sec = os::elapsedTime(); - - _cm->drainAllSATBBuffers(); - double finish_mark_ms = (os::elapsedTime() - start_time_sec) * 1000.0; - g1_policy()->record_satb_drain_time(finish_mark_ms); - - } - // Record the number of elements currently on the mark stack, so we - // only iterate over these. (Since evacuation may add to the mark - // stack, doing more exposes race conditions.) If no mark is in - // progress, this will be zero. - _cm->set_oops_do_bound(); - - assert(regions_accounted_for(), "Region leakage."); - - if (mark_in_progress()) - concurrent_mark()->newCSet(); - - // Now choose the CS. - g1_policy()->choose_collection_set(); - - // We may abandon a pause if we find no region that will fit in the MMU - // pause. - bool abandoned = (g1_policy()->collection_set() == NULL); - - // Nothing to do if we were unable to choose a collection set. - if (!abandoned) { + if (g1_policy()->should_initiate_conc_mark()) { + concurrent_mark()->checkpointRootsInitialPre(); + } + save_marks(); + + // We must do this before any possible evacuation that should propagate + // marks. + if (mark_in_progress()) { + double start_time_sec = os::elapsedTime(); + + _cm->drainAllSATBBuffers(); + double finish_mark_ms = (os::elapsedTime() - start_time_sec) * 1000.0; + g1_policy()->record_satb_drain_time(finish_mark_ms); + } + // Record the number of elements currently on the mark stack, so we + // only iterate over these. (Since evacuation may add to the mark + // stack, doing more exposes race conditions.) If no mark is in + // progress, this will be zero. + _cm->set_oops_do_bound(); + + assert(regions_accounted_for(), "Region leakage."); + + if (mark_in_progress()) + concurrent_mark()->newCSet(); + + // Now choose the CS. + g1_policy()->choose_collection_set(); + + // We may abandon a pause if we find no region that will fit in the MMU + // pause. + bool abandoned = (g1_policy()->collection_set() == NULL); + + // Nothing to do if we were unable to choose a collection set. + if (!abandoned) { #if G1_REM_SET_LOGGING - gclog_or_tty->print_cr("\nAfter pause, heap:"); - print(); + gclog_or_tty->print_cr("\nAfter pause, heap:"); + print(); #endif - setup_surviving_young_words(); - - // Set up the gc allocation regions. - get_gc_alloc_regions(); - - // Actually do the work... - evacuate_collection_set(); - free_collection_set(g1_policy()->collection_set()); - g1_policy()->clear_collection_set(); - - FREE_C_HEAP_ARRAY(bool, _in_cset_fast_test_base); - // this is more for peace of mind; we're nulling them here and - // we're expecting them to be null at the beginning of the next GC - _in_cset_fast_test = NULL; - _in_cset_fast_test_base = NULL; - - release_gc_alloc_regions(false /* totally */); - - cleanup_surviving_young_words(); - - if (g1_policy()->in_young_gc_mode()) { - _young_list->reset_sampled_info(); - assert(check_young_list_empty(true), - "young list should be empty"); + setup_surviving_young_words(); + + // Set up the gc allocation regions. + get_gc_alloc_regions(); + + // Actually do the work... + evacuate_collection_set(); + free_collection_set(g1_policy()->collection_set()); + g1_policy()->clear_collection_set(); + + FREE_C_HEAP_ARRAY(bool, _in_cset_fast_test_base); + // this is more for peace of mind; we're nulling them here and + // we're expecting them to be null at the beginning of the next GC + _in_cset_fast_test = NULL; + _in_cset_fast_test_base = NULL; + + release_gc_alloc_regions(false /* totally */); + + cleanup_surviving_young_words(); + + if (g1_policy()->in_young_gc_mode()) { + _young_list->reset_sampled_info(); + assert(check_young_list_empty(true), + "young list should be empty"); #if SCAN_ONLY_VERBOSE - _young_list->print(); + _young_list->print(); #endif // SCAN_ONLY_VERBOSE - g1_policy()->record_survivor_regions(_young_list->survivor_length(), - _young_list->first_survivor_region(), - _young_list->last_survivor_region()); - _young_list->reset_auxilary_lists(); + g1_policy()->record_survivor_regions(_young_list->survivor_length(), + _young_list->first_survivor_region(), + _young_list->last_survivor_region()); + _young_list->reset_auxilary_lists(); + } + } else { + COMPILER2_PRESENT(DerivedPointerTable::update_pointers()); } - } else { - COMPILER2_PRESENT(DerivedPointerTable::update_pointers()); - } - - if (evacuation_failed()) { - _summary_bytes_used = recalculate_used(); - } else { - // The "used" of the the collection set have already been subtracted - // when they were freed. Add in the bytes evacuated. - _summary_bytes_used += g1_policy()->bytes_in_to_space(); - } - - if (g1_policy()->in_young_gc_mode() && - g1_policy()->should_initiate_conc_mark()) { - concurrent_mark()->checkpointRootsInitialPost(); - set_marking_started(); - doConcurrentMark(); - } + + if (evacuation_failed()) { + _summary_bytes_used = recalculate_used(); + } else { + // The "used" of the the collection set have already been subtracted + // when they were freed. Add in the bytes evacuated. + _summary_bytes_used += g1_policy()->bytes_in_to_space(); + } + + if (g1_policy()->in_young_gc_mode() && + g1_policy()->should_initiate_conc_mark()) { + concurrent_mark()->checkpointRootsInitialPost(); + set_marking_started(); + doConcurrentMark(); + } #if SCAN_ONLY_VERBOSE - _young_list->print(); + _young_list->print(); #endif // SCAN_ONLY_VERBOSE - double end_time_sec = os::elapsedTime(); - double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS; - g1_policy()->record_pause_time_ms(pause_time_ms); - GCOverheadReporter::recordSTWEnd(end_time_sec); - g1_policy()->record_collection_pause_end(abandoned); - - assert(regions_accounted_for(), "Region leakage."); - - if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) { - HandleMark hm; // Discard invalid handles created during verification - gclog_or_tty->print(" VerifyAfterGC:"); - prepare_for_verify(); - Universe::verify(false); - } - - if (was_enabled) ref_processor()->enable_discovery(); - - { - size_t expand_bytes = g1_policy()->expansion_amount(); - if (expand_bytes > 0) { - size_t bytes_before = capacity(); - expand(expand_bytes); + double end_time_sec = os::elapsedTime(); + double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS; + g1_policy()->record_pause_time_ms(pause_time_ms); + GCOverheadReporter::recordSTWEnd(end_time_sec); + g1_policy()->record_collection_pause_end(abandoned); + + assert(regions_accounted_for(), "Region leakage."); + + if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) { + HandleMark hm; // Discard invalid handles created during verification + gclog_or_tty->print(" VerifyAfterGC:"); + prepare_for_verify(); + Universe::verify(false); } - } - - if (mark_in_progress()) { - concurrent_mark()->update_g1_committed(); - } + + if (was_enabled) ref_processor()->enable_discovery(); + + { + size_t expand_bytes = g1_policy()->expansion_amount(); + if (expand_bytes > 0) { + size_t bytes_before = capacity(); + expand(expand_bytes); + } + } + + if (mark_in_progress()) { + concurrent_mark()->update_g1_committed(); + } #ifdef TRACESPINNING - ParallelTaskTerminator::print_termination_counts(); + ParallelTaskTerminator::print_termination_counts(); #endif - gc_epilogue(false); - } - - assert(verify_region_lists(), "Bad region lists."); - - if (ExitAfterGCNum > 0 && total_collections() == ExitAfterGCNum) { - gclog_or_tty->print_cr("Stopping after GC #%d", ExitAfterGCNum); - print_tracing_info(); - vm_exit(-1); + gc_epilogue(false); + } + + assert(verify_region_lists(), "Bad region lists."); + + if (ExitAfterGCNum > 0 && total_collections() == ExitAfterGCNum) { + gclog_or_tty->print_cr("Stopping after GC #%d", ExitAfterGCNum); + print_tracing_info(); + vm_exit(-1); + } + } + + if (PrintHeapAtGC) { + Universe::print_heap_after_gc(); } } @@ -5357,7 +5392,7 @@ assert(_free_region_list == NULL, "Postcondition of loop."); if (_free_region_list_size != 0) { gclog_or_tty->print_cr("Size is %d.", _free_region_list_size); - print(); + print_on(gclog_or_tty, true /* extended */); } assert(_free_region_list_size == 0, "Postconditions of loop."); } diff -r e7d5557ad624 -r 0316eac49d5a src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Thu Jul 02 16:28:15 2009 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Tue Jul 07 14:23:00 2009 -0400 @@ -1061,8 +1061,14 @@ // Override; it uses the "prev" marking information virtual void verify(bool allow_dirty, bool silent); + // Default behavior by calling print(tty); virtual void print() const; + // This calls print_on(st, PrintHeapAtGCExtended). virtual void print_on(outputStream* st) const; + // If extended is true, it will print out information for all + // regions in the heap by calling print_on_extended(st). + virtual void print_on(outputStream* st, bool extended) const; + virtual void print_on_extended(outputStream* st) const; virtual void print_gc_threads_on(outputStream* st) const; virtual void gc_threads_do(ThreadClosure* tc) const; diff -r e7d5557ad624 -r 0316eac49d5a src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Thu Jul 02 16:28:15 2009 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Tue Jul 07 14:23:00 2009 -0400 @@ -1097,6 +1097,10 @@ _recorded_survivor_tail = tail; } + size_t recorded_survivor_regions() { + return _recorded_survivor_regions; + } + void record_thread_age_table(ageTable* age_table) { _survivors_age_table.merge_par(age_table); diff -r e7d5557ad624 -r 0316eac49d5a src/share/vm/gc_implementation/g1/heapRegion.cpp --- a/src/share/vm/gc_implementation/g1/heapRegion.cpp Thu Jul 02 16:28:15 2009 -0700 +++ b/src/share/vm/gc_implementation/g1/heapRegion.cpp Tue Jul 07 14:23:00 2009 -0400 @@ -703,7 +703,7 @@ } if (vl_cl.failures()) { gclog_or_tty->print_cr("Heap:"); - G1CollectedHeap::heap()->print(); + G1CollectedHeap::heap()->print_on(gclog_or_tty, true /* extended */); gclog_or_tty->print_cr(""); } if (VerifyDuringGC && diff -r e7d5557ad624 -r 0316eac49d5a src/share/vm/runtime/globals.hpp --- a/src/share/vm/runtime/globals.hpp Thu Jul 02 16:28:15 2009 -0700 +++ b/src/share/vm/runtime/globals.hpp Tue Jul 07 14:23:00 2009 -0400 @@ -1994,6 +1994,10 @@ product_rw(bool, PrintHeapAtGC, false, \ "Print heap layout before and after each GC") \ \ + product_rw(bool, PrintHeapAtGCExtended, false, \ + "Prints extended information about the layout of the heap " \ + "when -XX:+PrintHeapAtGC is set") \ + \ product(bool, PrintHeapAtSIGBREAK, true, \ "Print heap layout in response to SIGBREAK") \ \