8183121: Add information about scanned and skipped cards during UpdateRS
Summary: Log the number of scanned and skipped cards for the UpdateRS phase too.
Reviewed-by: mgerdin, sangheki
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp Tue Aug 08 22:58:44 2017 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp Wed Aug 09 17:27:42 2017 +0200
@@ -3237,7 +3237,7 @@
// investigate this in CR 7178365.
double sample_end_time_sec = os::elapsedTime();
double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
- size_t total_cards_scanned = g1_policy()->phase_times()->sum_thread_work_items(G1GCPhaseTimes::ScanRS, G1GCPhaseTimes::ScannedCards);
+ size_t total_cards_scanned = g1_policy()->phase_times()->sum_thread_work_items(G1GCPhaseTimes::ScanRS, G1GCPhaseTimes::ScanRSScannedCards);
g1_policy()->record_collection_pause_end(pause_time_ms, total_cards_scanned, heap_used_bytes_before_gc);
evacuation_info.set_collectionset_used_before(collection_set()->bytes_used_before());
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp Tue Aug 08 22:58:44 2017 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp Wed Aug 09 17:27:42 2017 +0200
@@ -81,14 +81,18 @@
_gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
_scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
- _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScannedCards);
+ _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
_scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
- _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ClaimedCards);
+ _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
_scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
- _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, SkippedCards);
+ _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
_update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
- _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
+ _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
+ _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
+ _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
+ _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
+ _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, ScanRSSkippedCards);
_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
_gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp Tue Aug 08 22:58:44 2017 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp Wed Aug 09 17:27:42 2017 +0200
@@ -78,9 +78,15 @@
};
enum GCScanRSWorkItems {
- ScannedCards,
- ClaimedCards,
- SkippedCards
+ ScanRSScannedCards,
+ ScanRSClaimedCards,
+ ScanRSSkippedCards
+ };
+
+ enum GCUpdateRSWorkItems {
+ UpdateRSProcessedBuffers,
+ UpdateRSScannedCards,
+ UpdateRSSkippedCards
};
private:
@@ -92,6 +98,8 @@
WorkerDataArray<double>* _gc_par_phases[GCParPhasesSentinel];
WorkerDataArray<size_t>* _update_rs_processed_buffers;
+ WorkerDataArray<size_t>* _update_rs_scanned_cards;
+ WorkerDataArray<size_t>* _update_rs_skipped_cards;
WorkerDataArray<size_t>* _scan_rs_scanned_cards;
WorkerDataArray<size_t>* _scan_rs_claimed_cards;
--- a/hotspot/src/share/vm/gc/g1/g1RemSet.cpp Tue Aug 08 22:58:44 2017 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1RemSet.cpp Wed Aug 09 17:27:42 2017 +0200
@@ -429,9 +429,9 @@
G1GCPhaseTimes* p = _g1p->phase_times();
p->record_time_secs(G1GCPhaseTimes::ScanRS, worker_i, scan_rs_time_sec);
- p->record_thread_work_item(G1GCPhaseTimes::ScanRS, worker_i, cl.cards_scanned(), G1GCPhaseTimes::ScannedCards);
- p->record_thread_work_item(G1GCPhaseTimes::ScanRS, worker_i, cl.cards_claimed(), G1GCPhaseTimes::ClaimedCards);
- p->record_thread_work_item(G1GCPhaseTimes::ScanRS, worker_i, cl.cards_skipped(), G1GCPhaseTimes::SkippedCards);
+ p->record_thread_work_item(G1GCPhaseTimes::ScanRS, worker_i, cl.cards_scanned(), G1GCPhaseTimes::ScanRSScannedCards);
+ p->record_thread_work_item(G1GCPhaseTimes::ScanRS, worker_i, cl.cards_claimed(), G1GCPhaseTimes::ScanRSClaimedCards);
+ p->record_thread_work_item(G1GCPhaseTimes::ScanRS, worker_i, cl.cards_skipped(), G1GCPhaseTimes::ScanRSSkippedCards);
p->record_time_secs(G1GCPhaseTimes::CodeRoots, worker_i, cl.strong_code_root_scan_time_sec());
}
@@ -440,9 +440,12 @@
class G1RefineCardClosure: public CardTableEntryClosure {
G1RemSet* _g1rs;
G1ScanObjsDuringUpdateRSClosure* _update_rs_cl;
+
+ size_t _cards_scanned;
+ size_t _cards_skipped;
public:
G1RefineCardClosure(G1CollectedHeap* g1h, G1ScanObjsDuringUpdateRSClosure* update_rs_cl) :
- _g1rs(g1h->g1_rem_set()), _update_rs_cl(update_rs_cl)
+ _g1rs(g1h->g1_rem_set()), _update_rs_cl(update_rs_cl), _cards_scanned(0), _cards_skipped(0)
{}
bool do_card_ptr(jbyte* card_ptr, uint worker_i) {
@@ -452,9 +455,18 @@
// In this case worker_i should be the id of a GC worker thread.
assert(SafepointSynchronize::is_at_safepoint(), "not during an evacuation pause");
- _g1rs->refine_card_during_gc(card_ptr, _update_rs_cl);
+ bool card_scanned = _g1rs->refine_card_during_gc(card_ptr, _update_rs_cl);
+
+ if (card_scanned) {
+ _cards_scanned++;
+ } else {
+ _cards_skipped++;
+ }
return true;
}
+
+ size_t cards_scanned() const { return _cards_scanned; }
+ size_t cards_skipped() const { return _cards_skipped; }
};
void G1RemSet::update_rem_set(G1ParScanThreadState* pss, uint worker_i) {
@@ -469,6 +481,10 @@
}
// Apply the closure to all remaining log entries.
_g1->iterate_dirty_card_closure(&refine_card_cl, worker_i);
+
+ G1GCPhaseTimes* p = _g1p->phase_times();
+ p->record_thread_work_item(G1GCPhaseTimes::UpdateRS, worker_i, refine_card_cl.cards_scanned(), G1GCPhaseTimes::UpdateRSScannedCards);
+ p->record_thread_work_item(G1GCPhaseTimes::UpdateRS, worker_i, refine_card_cl.cards_skipped(), G1GCPhaseTimes::UpdateRSSkippedCards);
}
void G1RemSet::cleanupHRRS() {
@@ -680,7 +696,7 @@
}
}
-void G1RemSet::refine_card_during_gc(jbyte* card_ptr,
+bool G1RemSet::refine_card_during_gc(jbyte* card_ptr,
G1ScanObjsDuringUpdateRSClosure* update_rs_cl) {
assert(_g1->is_gc_active(), "Only call during GC");
@@ -689,7 +705,7 @@
// If the card is no longer dirty, nothing to do. This covers cards that were already
// scanned as parts of the remembered sets.
if (*card_ptr != CardTableModRefBS::dirty_card_val()) {
- return;
+ return false;
}
// We claim lazily (so races are possible but they're benign), which reduces the
@@ -705,7 +721,7 @@
HeapWord* scan_limit = _scan_state->scan_top(card_region_idx);
if (scan_limit <= card_start) {
// If the card starts above the area in the region containing objects to scan, skip it.
- return;
+ return false;
}
// Don't use addr_for(card_ptr + 1) which can ask for
@@ -718,6 +734,7 @@
update_rs_cl->set_region(card_region);
bool card_processed = card_region->oops_on_card_seq_iterate_careful<true>(dirty_region, update_rs_cl);
assert(card_processed, "must be");
+ return true;
}
void G1RemSet::print_periodic_summary_info(const char* header, uint period_count) {
--- a/hotspot/src/share/vm/gc/g1/g1RemSet.hpp Tue Aug 08 22:58:44 2017 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1RemSet.hpp Wed Aug 09 17:27:42 2017 +0200
@@ -128,7 +128,8 @@
// Refine the card corresponding to "card_ptr", applying the given closure to
// all references found. Must only be called during gc.
- void refine_card_during_gc(jbyte* card_ptr, G1ScanObjsDuringUpdateRSClosure* update_rs_cl);
+ // Returns whether the card has been scanned.
+ bool refine_card_during_gc(jbyte* card_ptr, G1ScanObjsDuringUpdateRSClosure* update_rs_cl);
// Print accumulated summary info from the start of the VM.
void print_summary_info();
--- a/hotspot/test/gc/g1/TestGCLogMessages.java Tue Aug 08 22:58:44 2017 +0200
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java Wed Aug 09 17:27:42 2017 +0200
@@ -96,6 +96,8 @@
// Update RS
new LogMessageWithLevel("Update RS", Level.DEBUG),
new LogMessageWithLevel("Processed Buffers", Level.DEBUG),
+ new LogMessageWithLevel("Scanned Cards", Level.DEBUG),
+ new LogMessageWithLevel("Skipped Cards", Level.DEBUG),
new LogMessageWithLevel("Scan HCC", Level.TRACE),
// Scan RS
new LogMessageWithLevel("Scan RS", Level.DEBUG),