--- old/src/share/vm/gc/g1/g1CollectedHeap.cpp 2017-07-12 14:08:54.868596567 +0200 +++ new/src/share/vm/gc/g1/g1CollectedHeap.cpp 2017-07-12 14:08:54.769593503 +0200 @@ -3124,7 +3124,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()); --- old/src/share/vm/gc/g1/g1GCPhaseTimes.cpp 2017-07-12 14:08:55.441614301 +0200 +++ new/src/share/vm/gc/g1/g1GCPhaseTimes.cpp 2017-07-12 14:08:55.347611392 +0200 @@ -79,14 +79,18 @@ _gc_par_phases[Other] = new WorkerDataArray(max_gc_threads, "GC Worker Other (ms):"); _scan_rs_scanned_cards = new WorkerDataArray(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(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(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(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(max_gc_threads, "Scanned Cards:"); + _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards); + _update_rs_skipped_cards = new WorkerDataArray(max_gc_threads, "Skipped Cards:"); + _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, ScanRSSkippedCards); _termination_attempts = new WorkerDataArray(max_gc_threads, "Termination Attempts:"); _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); --- old/src/share/vm/gc/g1/g1GCPhaseTimes.hpp 2017-07-12 14:08:55.968630612 +0200 +++ new/src/share/vm/gc/g1/g1GCPhaseTimes.hpp 2017-07-12 14:08:55.871627610 +0200 @@ -77,9 +77,15 @@ }; enum GCScanRSWorkItems { - ScannedCards, - ClaimedCards, - SkippedCards + ScanRSScannedCards, + ScanRSClaimedCards, + ScanRSSkippedCards + }; + + enum GCUpdateRSWorkItems { + UpdateRSProcessedBuffers, + UpdateRSScannedCards, + UpdateRSSkippedCards }; private: @@ -91,6 +97,8 @@ WorkerDataArray* _gc_par_phases[GCParPhasesSentinel]; WorkerDataArray* _update_rs_processed_buffers; + WorkerDataArray* _update_rs_scanned_cards; + WorkerDataArray* _update_rs_skipped_cards; WorkerDataArray* _scan_rs_scanned_cards; WorkerDataArray* _scan_rs_claimed_cards; --- old/src/share/vm/gc/g1/g1RemSet.cpp 2017-07-12 14:08:56.498647015 +0200 +++ new/src/share/vm/gc/g1/g1RemSet.cpp 2017-07-12 14:08:56.401644013 +0200 @@ -430,9 +430,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()); } @@ -441,17 +441,29 @@ 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) { 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) { @@ -466,6 +478,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() { @@ -677,7 +693,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"); @@ -686,7 +702,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; } // During GC we can immediately clean the card since we will not re-enqueue stale @@ -701,7 +717,7 @@ HeapWord* scan_limit = _scan_state->scan_top(r->hrm_index()); 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 @@ -713,6 +729,7 @@ update_rs_cl->set_region(r); bool card_processed = r->oops_on_card_seq_iterate_careful(dirty_region, update_rs_cl); assert(card_processed, "must be"); + return true; } void G1RemSet::print_periodic_summary_info(const char* header, uint period_count) { --- old/src/share/vm/gc/g1/g1RemSet.hpp 2017-07-12 14:08:57.021663202 +0200 +++ new/src/share/vm/gc/g1/g1RemSet.hpp 2017-07-12 14:08:56.926660262 +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(); --- old/test/gc/g1/TestGCLogMessages.java 2017-07-12 14:08:57.545679420 +0200 +++ new/test/gc/g1/TestGCLogMessages.java 2017-07-12 14:08:57.443676263 +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),