8035398: Add card redirty time in "Other" time in G1
Summary: Show the time taken by card redirtying during GC in a new "Redirty Cards" line.
Reviewed-by: jwilhelm, brutisso
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Mar 17 10:13:18 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Mar 17 10:13:27 2014 +0100
@@ -169,14 +169,6 @@
int calls() { return _calls; }
};
-class RedirtyLoggedCardTableEntryFastClosure : public CardTableEntryClosure {
-public:
- bool do_card_ptr(jbyte* card_ptr, int worker_i) {
- *card_ptr = CardTableModRefBS::dirty_card_val();
- return true;
- }
-};
-
YoungList::YoungList(G1CollectedHeap* g1h) :
_g1h(g1h), _head(NULL), _length(0), _last_sampled_rs_lengths(0),
_survivor_head(NULL), _survivor_tail(NULL), _survivor_length(0) {
@@ -5270,6 +5262,29 @@
}
}
+class RedirtyLoggedCardTableEntryFastClosure : public CardTableEntryClosure {
+public:
+ bool do_card_ptr(jbyte* card_ptr, int worker_i) {
+ *card_ptr = CardTableModRefBS::dirty_card_val();
+ return true;
+ }
+};
+
+void G1CollectedHeap::redirty_logged_cards() {
+ guarantee(G1DeferredRSUpdate, "Must only be called when using deferred RS updates.");
+ double redirty_logged_cards_start = os::elapsedTime();
+
+ RedirtyLoggedCardTableEntryFastClosure redirty;
+ dirty_card_queue_set().set_closure(&redirty);
+ dirty_card_queue_set().apply_closure_to_all_completed_buffers();
+
+ DirtyCardQueueSet& dcq = JavaThread::dirty_card_queue_set();
+ dcq.merge_bufferlists(&dirty_card_queue_set());
+ assert(dirty_card_queue_set().completed_buffers_num() == 0, "All should be consumed");
+
+ g1_policy()->phase_times()->record_redirty_logged_cards_time_ms((os::elapsedTime() - redirty_logged_cards_start) * 1000.0);
+}
+
// Weak Reference Processing support
// An always "is_alive" closure that is used to preserve referents.
@@ -5926,13 +5941,7 @@
enqueue_discovered_references(n_workers);
if (G1DeferredRSUpdate) {
- RedirtyLoggedCardTableEntryFastClosure redirty;
- dirty_card_queue_set().set_closure(&redirty);
- dirty_card_queue_set().apply_closure_to_all_completed_buffers();
-
- DirtyCardQueueSet& dcq = JavaThread::dirty_card_queue_set();
- dcq.merge_bufferlists(&dirty_card_queue_set());
- assert(dirty_card_queue_set().completed_buffers_num() == 0, "All should be consumed");
+ redirty_logged_cards();
}
COMPILER2_PRESENT(DerivedPointerTable::update_pointers());
}
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Mon Mar 17 10:13:18 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Mon Mar 17 10:13:27 2014 +0100
@@ -1651,6 +1651,8 @@
// in symbol table, possibly in parallel.
void unlink_string_and_symbol_table(BoolObjectClosure* is_alive, bool unlink_strings = true, bool unlink_symbols = true);
+ // Redirty logged cards in the refinement queue.
+ void redirty_logged_cards();
// Verification
// The following is just to alert the verification code
--- a/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Mon Mar 17 10:13:18 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Mon Mar 17 10:13:27 2014 +0100
@@ -314,6 +314,9 @@
_recorded_non_young_cset_choice_time_ms));
print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
+ if (G1DeferredRSUpdate) {
+ print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
+ }
print_stats(2, "Free CSet",
(_recorded_young_free_cset_time_ms +
_recorded_non_young_free_cset_time_ms));
--- a/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Mon Mar 17 10:13:18 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Mon Mar 17 10:13:27 2014 +0100
@@ -143,6 +143,8 @@
double _recorded_young_cset_choice_time_ms;
double _recorded_non_young_cset_choice_time_ms;
+ double _recorded_redirty_logged_cards_time_ms;
+
double _recorded_young_free_cset_time_ms;
double _recorded_non_young_free_cset_time_ms;
@@ -256,6 +258,10 @@
_recorded_non_young_cset_choice_time_ms = time_ms;
}
+ void record_redirty_logged_cards_time_ms(double time_ms) {
+ _recorded_redirty_logged_cards_time_ms = time_ms;
+ }
+
void record_cur_collection_start_sec(double time_ms) {
_cur_collection_start_sec = time_ms;
}
--- a/hotspot/test/gc/g1/TestGCLogMessages.java Mon Mar 17 10:13:18 2014 +0100
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java Mon Mar 17 10:13:27 2014 +0100
@@ -23,7 +23,7 @@
/*
* @test TestPrintGCDetails
- * @bug 8035406 8027295
+ * @bug 8035406 8027295 8035398
* @summary Ensure that the PrintGCDetails output for a minor GC with G1
* includes the expected necessary messages.
* @key gc
@@ -42,6 +42,7 @@
OutputAnalyzer output = new OutputAnalyzer(pb.start());
+ output.shouldNotContain("[Redirty Cards");
output.shouldNotContain("[Code Root Purge");
output.shouldNotContain("[Young Free CSet");
output.shouldNotContain("[Non-Young Free CSet");
@@ -54,6 +55,7 @@
output = new OutputAnalyzer(pb.start());
+ output.shouldContain("[Redirty Cards");
output.shouldContain("[Code Root Purge");
output.shouldNotContain("[Young Free CSet");
output.shouldNotContain("[Non-Young Free CSet");
@@ -68,6 +70,7 @@
output = new OutputAnalyzer(pb.start());
+ output.shouldContain("[Redirty Cards");
output.shouldContain("[Code Root Purge");
output.shouldContain("[Young Free CSet");
output.shouldContain("[Non-Young Free CSet");