8201596: java.lang.ref.Reference processing total time logging broken
Summary: Fix "Reference Processing" and add "Weak Processing" time
Reviewed-by: kbarrett, sangheki
--- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp Wed Apr 18 11:36:48 2018 +0200
+++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp Wed Apr 18 11:36:48 2018 +0200
@@ -4201,7 +4201,7 @@
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()) {
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp Wed Apr 18 11:36:48 2018 +0200
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp Wed Apr 18 11:36:48 2018 +0200
@@ -131,6 +131,7 @@
_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 @@
_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 @@
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]);
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp Wed Apr 18 11:36:48 2018 +0200
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp Wed Apr 18 11:36:48 2018 +0200
@@ -129,6 +129,8 @@
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 @@
_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;
}
--- a/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java Wed Apr 18 11:36:48 2018 +0200
+++ b/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java Wed Apr 18 11:36:48 2018 +0200
@@ -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 @@
// 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),