From 20c2e53dd8dc98bde90d54c89808064ec9f7c90b Mon Sep 17 00:00:00 2001 From: johnc Date: Thu, 16 May 2013 09:24:26 -0700 Subject: [PATCH] 8010738: G1: Output for full GCs with +PrintGCDetails should contain perm gen size/meta data change info Summary: Include metaspace information (used, allocated, reserved) in the PrintGCDetails output for full GCs. Reviewed-by: poonam, jmasa, brutisso --- .../gc_implementation/g1/g1CollectedHeap.cpp | 2 +- .../g1/g1CollectorPolicy.cpp | 110 ++++++++++-------- .../g1/g1CollectorPolicy.hpp | 19 +-- test/gc/g1/TestPrintGCDetails.java | 57 +++++++++ 4 files changed, 129 insertions(+), 59 deletions(-) create mode 100644 test/gc/g1/TestPrintGCDetails.java diff --git a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp index 49cde4272..11dcb0beb 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @@ -1549,7 +1549,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc, } if (G1Log::finer()) { - g1_policy()->print_detailed_heap_transition(); + g1_policy()->print_detailed_heap_transition(true /* full */); } print_heap_after_gc(); diff --git a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp index a21290c83..741c6b713 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @@ -124,9 +124,12 @@ G1CollectorPolicy::G1CollectorPolicy() : _last_young_gc(false), _last_gc_was_young(false), - _eden_bytes_before_gc(0), - _survivor_bytes_before_gc(0), - _capacity_before_gc(0), + _eden_used_bytes_before_gc(0), + _survivor_used_bytes_before_gc(0), + _heap_used_bytes_before_gc(0), + _metaspace_used_bytes_before_gc(0), + _eden_capacity_bytes_before_gc(0), + _heap_capacity_bytes_before_gc(0), _eden_cset_region_length(0), _survivor_cset_region_length(0), @@ -746,7 +749,7 @@ G1CollectorPolicy::verify_young_ages(HeapRegion* head, void G1CollectorPolicy::record_full_collection_start() { _full_collection_start_sec = os::elapsedTime(); - record_heap_size_info_at_start(); + record_heap_size_info_at_start(true /* full */); // Release the future to-space so that it is available for compaction into. _g1->set_full_collection(); } @@ -803,7 +806,7 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec) { _trace_gen0_time_data.record_start_collection(s_w_t_ms); _stop_world_start = 0.0; - record_heap_size_info_at_start(); + record_heap_size_info_at_start(false /* full */); phase_times()->record_cur_collection_start_sec(start_time_sec); _pending_cards = _g1->pending_card_num(); @@ -938,14 +941,6 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) { _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0, end_time_sec, false); - size_t freed_bytes = - _cur_collection_pause_used_at_start_bytes - cur_used_bytes; - size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes; - - double survival_fraction = - (double)surviving_bytes/ - (double)_collection_set_bytes_used_before; - if (update_stats) { _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times()); // this is where we update the allocation rate of the application @@ -998,6 +993,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) { } } } + bool new_in_marking_window = _in_marking_window; bool new_in_marking_window_im = false; if (during_initial_mark_pause()) { @@ -1083,8 +1079,10 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) { } _rs_length_diff_seq->add((double) rs_length_diff); - size_t copied_bytes = surviving_bytes; + size_t freed_bytes = _heap_used_bytes_before_gc - cur_used_bytes; + size_t copied_bytes = _collection_set_bytes_used_before - freed_bytes; double cost_per_byte_ms = 0.0; + if (copied_bytes > 0) { cost_per_byte_ms = phase_times()->average_last_obj_copy_time() / (double) copied_bytes; if (_in_marking_window) { @@ -1148,51 +1146,61 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) { byte_size_in_proper_unit((double)(bytes)), \ proper_unit_for_byte_size((bytes)) -void G1CollectorPolicy::record_heap_size_info_at_start() { +void G1CollectorPolicy::record_heap_size_info_at_start(bool full) { YoungList* young_list = _g1->young_list(); - _eden_bytes_before_gc = young_list->eden_used_bytes(); - _survivor_bytes_before_gc = young_list->survivor_used_bytes(); - _capacity_before_gc = _g1->capacity(); - - _cur_collection_pause_used_at_start_bytes = _g1->used(); + _eden_used_bytes_before_gc = young_list->eden_used_bytes(); + _survivor_used_bytes_before_gc = young_list->survivor_used_bytes(); + _heap_capacity_bytes_before_gc = _g1->capacity(); + _heap_used_bytes_before_gc = _g1->used(); _cur_collection_pause_used_regions_at_start = _g1->used_regions(); - size_t eden_capacity_before_gc = - (_young_list_target_length * HeapRegion::GrainBytes) - _survivor_bytes_before_gc; + _eden_capacity_bytes_before_gc = + (_young_list_target_length * HeapRegion::GrainBytes) - _survivor_used_bytes_before_gc; - _prev_eden_capacity = eden_capacity_before_gc; + if (full) { + _metaspace_used_bytes_before_gc = MetaspaceAux::allocated_used_bytes(); + } } void G1CollectorPolicy::print_heap_transition() { _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(); - size_t used_before_gc = _cur_collection_pause_used_at_start_bytes; - size_t used = _g1->used(); - size_t capacity = _g1->capacity(); - size_t eden_capacity = - (_young_list_target_length * HeapRegion::GrainBytes) - survivor_bytes; - - gclog_or_tty->print_cr( - " [Eden: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->"EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT") " - "Survivors: "EXT_SIZE_FORMAT"->"EXT_SIZE_FORMAT" " - "Heap: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->" - EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")]", - EXT_SIZE_PARAMS(_eden_bytes_before_gc), - EXT_SIZE_PARAMS(_prev_eden_capacity), - EXT_SIZE_PARAMS(eden_bytes), - EXT_SIZE_PARAMS(eden_capacity), - EXT_SIZE_PARAMS(_survivor_bytes_before_gc), - EXT_SIZE_PARAMS(survivor_bytes), - EXT_SIZE_PARAMS(used_before_gc), - EXT_SIZE_PARAMS(_capacity_before_gc), - EXT_SIZE_PARAMS(used), - EXT_SIZE_PARAMS(capacity)); + _heap_used_bytes_before_gc, + _g1->used(), + _g1->capacity()); +} + +void G1CollectorPolicy::print_detailed_heap_transition(bool full) { + YoungList* young_list = _g1->young_list(); + + size_t eden_used_bytes_after_gc = young_list->eden_used_bytes(); + size_t survivor_used_bytes_after_gc = young_list->survivor_used_bytes(); + size_t heap_used_bytes_after_gc = _g1->used(); + + size_t heap_capacity_bytes_after_gc = _g1->capacity(); + size_t eden_capacity_bytes_after_gc = + (_young_list_target_length * HeapRegion::GrainBytes) - survivor_used_bytes_after_gc; + + gclog_or_tty->print( + " [Eden: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->"EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT") " + "Survivors: "EXT_SIZE_FORMAT"->"EXT_SIZE_FORMAT" " + "Heap: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->" + EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")]", + EXT_SIZE_PARAMS(_eden_used_bytes_before_gc), + EXT_SIZE_PARAMS(_eden_capacity_bytes_before_gc), + EXT_SIZE_PARAMS(eden_used_bytes_after_gc), + EXT_SIZE_PARAMS(eden_capacity_bytes_after_gc), + EXT_SIZE_PARAMS(_survivor_used_bytes_before_gc), + EXT_SIZE_PARAMS(survivor_used_bytes_after_gc), + EXT_SIZE_PARAMS(_heap_used_bytes_before_gc), + EXT_SIZE_PARAMS(_heap_capacity_bytes_before_gc), + EXT_SIZE_PARAMS(heap_used_bytes_after_gc), + EXT_SIZE_PARAMS(heap_capacity_bytes_after_gc)); + + if (full) { + MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_gc); + } + + gclog_or_tty->cr(); } void G1CollectorPolicy::adjust_concurrent_refinement(double update_rs_time, diff --git a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp index 088678503..90106c00a 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp @@ -175,7 +175,6 @@ private: CollectionSetChooser* _collectionSetChooser; double _full_collection_start_sec; - size_t _cur_collection_pause_used_at_start_bytes; uint _cur_collection_pause_used_regions_at_start; // These exclude marking times. @@ -194,7 +193,6 @@ private: uint _young_list_target_length; uint _young_list_fixed_length; - size_t _prev_eden_capacity; // used for logging // The max number of regions we can extend the eden by while the GC // locker is active. This should be >= _young_list_target_length; @@ -693,11 +691,11 @@ public: // Records the information about the heap size for reporting in // print_detailed_heap_transition - void record_heap_size_info_at_start(); + void record_heap_size_info_at_start(bool full); // Print heap sizing transition (with less and more detail). void print_heap_transition(); - void print_detailed_heap_transition(); + void print_detailed_heap_transition(bool full = false); void record_stop_world_start(); void record_concurrent_pause(); @@ -861,9 +859,16 @@ private: uint _max_survivor_regions; // For reporting purposes. - size_t _eden_bytes_before_gc; - size_t _survivor_bytes_before_gc; - size_t _capacity_before_gc; + // The value of _heap_bytes_before_gc is also used to calculate + // the cost of copying. + + size_t _eden_used_bytes_before_gc; // Eden occupancy before GC + size_t _survivor_used_bytes_before_gc; // Survivor occupancy before GC + size_t _heap_used_bytes_before_gc; // Heap occupancy before GC + size_t _metaspace_used_bytes_before_gc; // Metaspace occupancy before GC + + size_t _eden_capacity_bytes_before_gc; // Eden capacity before GC + size_t _heap_capacity_bytes_before_gc; // Heap capacity before GC // The amount of survivor regions after a collection. uint _recorded_survivor_regions; diff --git a/test/gc/g1/TestPrintGCDetails.java b/test/gc/g1/TestPrintGCDetails.java new file mode 100644 index 000000000..4280a19cd --- /dev/null +++ b/test/gc/g1/TestPrintGCDetails.java @@ -0,0 +1,57 @@ +/* + * Copyright (c) 2013, 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 + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +/* + * @test TestPrintGCDetails + * @bug 8010738 + * @summary Ensure that the PrintGCDetails for a full GC with G1 includes Metaspace. + * @key gc + * @key regression + * @library /testlibrary + */ + +import com.oracle.java.testlibrary.ProcessTools; +import com.oracle.java.testlibrary.OutputAnalyzer; + +public class TestPrintGCDetails { + public static void main(String[] args) throws Exception { + + ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", + "-XX:+PrintGCDetails", + SystemGCTest.class.getName()); + + OutputAnalyzer output = new OutputAnalyzer(pb.start()); + + System.out.println("Output:\n" + output.getOutput()); + + output.shouldContain("Metaspace"); + output.shouldHaveExitValue(0); + } + + static class SystemGCTest { + public static void main(String [] args) { + System.out.println("Calling System.gc()"); + System.gc(); + } + } +} -- GitLab