infernap12/jdk
1
0
Fork 0
mirror of https://github.com/openjdk/jdk.git synced 2026-04-20 20:00:28 +00:00
Code Issues Packages Projects Releases Wiki Activity

8155094: Add logging for long lasting methods found in JDK-8152948

Browse Source 
Adds logging for DerivedPointerTable, TLAB preparation and resizing, and new collection set setup work

Reviewed-by: kbarrett, sangheki
This commit is contained in:
Thomas Schatzl 2017-03-16 09:05:20 +01:00
parent 4b9562288f
commit 6a9ca1701d
5 changed files with 64 additions and 11 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

32
hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
View File

@ -1378,10 +1378,9 @@ bool G1CollectedHeap::do_full_collection(bool explicit_gc,
}
_verifier->check_bitmaps("Full GC End");
// Start a new incremental collection set for the next pause
collection_set()->start_incremental_building();
clear_cset_fast_test();
double start = os::elapsedTime();
start_new_collection_set();
g1_policy()->phase_times()->record_start_new_cset_time_ms((os::elapsedTime() - start) * 1000.0);
_allocator->init_mutator_alloc_region();
@ -2694,9 +2693,12 @@ G1CollectedHeap* G1CollectedHeap::heap() {
void G1CollectedHeap::gc_prologue(bool full /* Ignored */) {
// always_do_update_barrier = false;
assert(InlineCacheBuffer::is_empty(), "should have cleaned up ICBuffer");
double start = os::elapsedTime();
// Fill TLAB's and such
accumulate_statistics_all_tlabs();
ensure_parsability(true);
g1_policy()->phase_times()->record_prepare_tlab_time_ms((os::elapsedTime() - start) * 1000.0);
g1_rem_set()->print_periodic_summary_info("Before GC RS summary", total_collections());
}
@ -2713,7 +2715,10 @@ void G1CollectedHeap::gc_epilogue(bool full) {
#endif
// always_do_update_barrier = true;
double start = os::elapsedTime();
resize_all_tlabs();
g1_policy()->phase_times()->record_resize_tlab_time_ms((os::elapsedTime() - start) * 1000.0);
allocation_context_stats().update(full);
// We have just completed a GC. Update the soft reference
@ -2996,6 +3001,15 @@ public:
}
};
void G1CollectedHeap::start_new_collection_set() {
collection_set()->start_incremental_building();
clear_cset_fast_test();
guarantee(_eden.length() == 0, "eden should have been cleared");
g1_policy()->transfer_survivors_to_cset(survivor());
}
bool
G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
assert_at_safepoint(true /* should_be_vm_thread */);
@ -3198,13 +3212,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
_survivor_evac_stats.adjust_desired_plab_sz();
_old_evac_stats.adjust_desired_plab_sz();
// Start a new incremental collection set for the next pause.
collection_set()->start_incremental_building();
clear_cset_fast_test();
guarantee(_eden.length() == 0, "eden should have been cleared");
g1_policy()->transfer_survivors_to_cset(survivor());
start_new_collection_set();
if (evacuation_failed()) {
set_used(recalculate_used());
@ -4522,7 +4530,9 @@ void G1CollectedHeap::post_evacuate_collection_set(EvacuationInfo& evacuation_in
redirty_logged_cards();
#if defined(COMPILER2) || INCLUDE_JVMCI
double start = os::elapsedTime();
DerivedPointerTable::update_pointers();
g1_policy()->phase_times()->record_derived_pointer_table_update_time((os::elapsedTime() - start) * 1000.0);
#endif
g1_policy()->print_age_table();
}

2
hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp
View File

@ -159,6 +159,8 @@ private:
HeapRegionSet _humongous_set;
void eagerly_reclaim_humongous_regions();
// Start a new incremental collection set for the next pause.
void start_new_collection_set();
// The number of regions we could create by expansion.
uint _expansion_regions;

12
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp
View File

@ -112,6 +112,9 @@ void G1GCPhaseTimes::reset() {
_cur_evac_fail_restore_remsets = 0.0;
_cur_evac_fail_remove_self_forwards = 0.0;
_cur_string_dedup_fixup_time_ms = 0.0;
_cur_prepare_tlab_time_ms = 0.0;
_cur_resize_tlab_time_ms = 0.0;
_cur_derived_pointer_table_update_time_ms = 0.0;
_cur_clear_ct_time_ms = 0.0;
_cur_expand_heap_time_ms = 0.0;
_cur_ref_proc_time_ms = 0.0;
@ -125,6 +128,7 @@ void G1GCPhaseTimes::reset() {
_recorded_redirty_logged_cards_time_ms = 0.0;
_recorded_preserve_cm_referents_time_ms = 0.0;
_recorded_merge_pss_time_ms = 0.0;
_recorded_start_new_cset_time_ms = 0.0;
_recorded_total_free_cset_time_ms = 0.0;
_recorded_serial_free_cset_time_ms = 0.0;
_cur_fast_reclaim_humongous_time_ms = 0.0;
@ -288,6 +292,7 @@ double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
if (_root_region_scan_wait_time_ms > 0.0) {
debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
if (G1EagerReclaimHumongousObjects) {
debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
@ -375,6 +380,9 @@ double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
#if defined(COMPILER2) || INCLUDE_JVMCI
debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
#endif
if (_recorded_clear_claimed_marks_time_ms > 0.0) {
debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
}
@ -390,6 +398,10 @@ double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
}
debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
if (UseTLAB && ResizeTLAB) {
debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
}
debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);

23
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp
View File

@ -97,6 +97,11 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
double _cur_string_dedup_fixup_time_ms;
double _cur_prepare_tlab_time_ms;
double _cur_resize_tlab_time_ms;
double _cur_derived_pointer_table_update_time_ms;
double _cur_clear_ct_time_ms;
double _cur_expand_heap_time_ms;
double _cur_ref_proc_time_ms;
@ -118,6 +123,8 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
double _recorded_merge_pss_time_ms;
double _recorded_start_new_cset_time_ms;
double _recorded_total_free_cset_time_ms;
double _recorded_serial_free_cset_time_ms;
@ -172,6 +179,18 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
public:
void record_prepare_tlab_time_ms(double ms) {
_cur_prepare_tlab_time_ms = ms;
}
void record_resize_tlab_time_ms(double ms) {
_cur_resize_tlab_time_ms = ms;
}
void record_derived_pointer_table_update_time(double ms) {
_cur_derived_pointer_table_update_time_ms = ms;
}
void record_clear_ct_time(double ms) {
_cur_clear_ct_time_ms = ms;
}
@ -259,6 +278,10 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
_recorded_merge_pss_time_ms = time_ms;
}
void record_start_new_cset_time_ms(double time_ms) {
_recorded_start_new_cset_time_ms = time_ms;
}
void record_cur_collection_start_sec(double time_ms) {
_cur_collection_start_sec = time_ms;
}

6
hotspot/test/gc/g1/TestGCLogMessages.java
View File

@ -115,6 +115,12 @@ public class TestGCLogMessages {
new LogMessageWithLevel("Preserve CM Refs", Level.DEBUG),
// Merge PSS
new LogMessageWithLevel("Merge Per-Thread State", Level.DEBUG),
// TLAB handling
new LogMessageWithLevel("Prepare TLABs", Level.DEBUG),
new LogMessageWithLevel("Resize TLABs", Level.DEBUG),
new LogMessageWithLevel("DerivedPointerTable Update", Level.DEBUG),
new LogMessageWithLevel("Start New Collection Set", Level.DEBUG),
};
void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception {