8201596: java.lang.ref.Reference processing total time logging broken

Fix "Reference Processing" and add "Weak Processing" time

Reviewed-by: kbarrett, sangheki
This commit is contained in:
Thomas Schatzl 2018-04-18 11:36:48 +02:00
parent c62a6abe91
commit ebbd7cf90b
4 changed files with 14 additions and 2 deletions

View File

@ -4201,7 +4201,7 @@ void G1CollectedHeap::post_evacuate_collection_set(EvacuationInfo& evacuation_in
WeakProcessor::weak_oops_do(&is_alive, &keep_alive);
double time_ms = (os::elapsedTime() - start) * 1000.0;
g1_policy()->phase_times()->record_ref_proc_time(time_ms);
g1_policy()->phase_times()->record_weak_ref_proc_time(time_ms);
}
if (G1StringDedup::is_enabled()) {

View File

@ -131,6 +131,7 @@ void G1GCPhaseTimes::reset() {
_cur_expand_heap_time_ms = 0.0;
_cur_ref_proc_time_ms = 0.0;
_cur_ref_enq_time_ms = 0.0;
_cur_weak_ref_proc_time_ms = 0.0;
_cur_collection_start_sec = 0.0;
_root_region_scan_wait_time_ms = 0.0;
_external_accounted_time_ms = 0.0;
@ -372,6 +373,7 @@ double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
_cur_collection_code_root_fixup_time_ms +
_recorded_preserve_cm_referents_time_ms +
_cur_ref_proc_time_ms +
_cur_weak_ref_proc_time_ms +
_cur_ref_enq_time_ms +
_cur_clear_ct_time_ms +
_recorded_merge_pss_time_ms +
@ -392,6 +394,8 @@ double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
_ref_phase_times.print_all_references(2, false);
debug_time("Weak Processing", _cur_weak_ref_proc_time_ms);
if (G1StringDedup::is_enabled()) {
debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
debug_phase(_gc_par_phases[StringDedupQueueFixup]);

View File

@ -129,6 +129,8 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
double _cur_ref_proc_time_ms;
double _cur_ref_enq_time_ms;
double _cur_weak_ref_proc_time_ms;
double _cur_collection_start_sec;
double _root_region_scan_wait_time_ms;
@ -253,6 +255,10 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
_cur_ref_proc_time_ms = ms;
}
void record_weak_ref_proc_time(double ms) {
_cur_weak_ref_proc_time_ms = ms;
}
void record_ref_enq_time(double ms) {
_cur_ref_enq_time_ms = ms;
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2014, 2017, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2014, 2018, 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
@ -144,6 +144,8 @@ public class TestGCLogMessages {
// Reference Processing
new LogMessageWithLevel("Reference Processing", Level.DEBUG),
new LogMessageWithLevel("Reference Enqueuing", Level.DEBUG),
// VM internal reference processing
new LogMessageWithLevel("Weak Processing", Level.DEBUG),
new LogMessageWithLevelC2OrJVMCIOnly("DerivedPointerTable Update", Level.DEBUG),
new LogMessageWithLevel("Start New Collection Set", Level.DEBUG),