2297 // Clean cards in the hot card cache |
2297 // Clean cards in the hot card cache |
2298 G1HotCardCache* hot_card_cache = _cg1r->hot_card_cache(); |
2298 G1HotCardCache* hot_card_cache = _cg1r->hot_card_cache(); |
2299 hot_card_cache->drain(worker_i, g1_rem_set(), into_cset_dcq); |
2299 hot_card_cache->drain(worker_i, g1_rem_set(), into_cset_dcq); |
2300 |
2300 |
2301 DirtyCardQueueSet& dcqs = JavaThread::dirty_card_queue_set(); |
2301 DirtyCardQueueSet& dcqs = JavaThread::dirty_card_queue_set(); |
2302 int n_completed_buffers = 0; |
2302 size_t n_completed_buffers = 0; |
2303 while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) { |
2303 while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) { |
2304 n_completed_buffers++; |
2304 n_completed_buffers++; |
2305 } |
2305 } |
2306 g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i, n_completed_buffers); |
2306 g1_policy()->phase_times()->record_thread_work_item(G1GCPhaseTimes::UpdateRS, worker_i, n_completed_buffers); |
2307 dcqs.clear_n_completed_buffers(); |
2307 dcqs.clear_n_completed_buffers(); |
2308 assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); |
2308 assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); |
2309 } |
2309 } |
2310 |
2310 |
2311 |
2311 |
3910 |
3910 |
3911 _gc_tracer_stw->report_yc_type(yc_type()); |
3911 _gc_tracer_stw->report_yc_type(yc_type()); |
3912 |
3912 |
3913 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); |
3913 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); |
3914 |
3914 |
3915 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? |
3915 uint active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? |
3916 workers()->active_workers() : 1); |
3916 workers()->active_workers() : 1); |
3917 double pause_start_sec = os::elapsedTime(); |
3917 double pause_start_sec = os::elapsedTime(); |
3918 g1_policy()->phase_times()->note_gc_start(active_workers); |
3918 g1_policy()->phase_times()->note_gc_start(active_workers, mark_in_progress()); |
3919 log_gc_header(); |
3919 log_gc_header(); |
3920 |
3920 |
3921 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); |
3921 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); |
3922 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); |
3922 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); |
3923 |
3923 |
4743 |
4742 |
4744 { |
4743 { |
4745 double start = os::elapsedTime(); |
4744 double start = os::elapsedTime(); |
4746 G1ParEvacuateFollowersClosure evac(_g1h, &pss, _queues, &_terminator); |
4745 G1ParEvacuateFollowersClosure evac(_g1h, &pss, _queues, &_terminator); |
4747 evac.do_void(); |
4746 evac.do_void(); |
4748 double elapsed_ms = (os::elapsedTime()-start)*1000.0; |
4747 double elapsed_sec = os::elapsedTime() - start; |
4749 double term_ms = pss.term_time()*1000.0; |
4748 double term_sec = pss.term_time(); |
4750 _g1h->g1_policy()->phase_times()->add_obj_copy_time(worker_id, elapsed_ms-term_ms); |
4749 _g1h->g1_policy()->phase_times()->add_time_secs(G1GCPhaseTimes::ObjCopy, worker_id, elapsed_sec - term_sec); |
4751 _g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts()); |
4750 _g1h->g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::Termination, worker_id, term_sec); |
|
4751 _g1h->g1_policy()->phase_times()->record_thread_work_item(G1GCPhaseTimes::Termination, worker_id, pss.term_attempts()); |
4752 } |
4752 } |
4753 _g1h->g1_policy()->record_thread_age_table(pss.age_table()); |
4753 _g1h->g1_policy()->record_thread_age_table(pss.age_table()); |
4754 _g1h->update_surviving_young_words(pss.surviving_young_words()+1); |
4754 _g1h->update_surviving_young_words(pss.surviving_young_words()+1); |
4755 |
4755 |
4756 if (ParallelGCVerbose) { |
4756 if (ParallelGCVerbose) { |
4762 |
4762 |
4763 // Close the inner scope so that the ResourceMark and HandleMark |
4763 // Close the inner scope so that the ResourceMark and HandleMark |
4764 // destructors are executed here and are included as part of the |
4764 // destructors are executed here and are included as part of the |
4765 // "GC Worker Time". |
4765 // "GC Worker Time". |
4766 } |
4766 } |
4767 |
4767 _g1h->g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::GCWorkerEnd, worker_id, os::elapsedTime()); |
4768 double end_time_ms = os::elapsedTime() * 1000.0; |
|
4769 _g1h->g1_policy()->phase_times()->record_gc_worker_end_time(worker_id, end_time_ms); |
|
4770 } |
4768 } |
4771 }; |
4769 }; |
4772 |
4770 |
4773 // *** Common G1 Evacuation Stuff |
4771 // *** Common G1 Evacuation Stuff |
4774 |
4772 |
4826 buf_scan_non_heap_weak_roots.done(); |
4824 buf_scan_non_heap_weak_roots.done(); |
4827 |
4825 |
4828 double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds() |
4826 double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds() |
4829 + buf_scan_non_heap_weak_roots.closure_app_seconds(); |
4827 + buf_scan_non_heap_weak_roots.closure_app_seconds(); |
4830 |
4828 |
4831 g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); |
4829 g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::ObjCopy, worker_i, obj_copy_time_sec); |
4832 |
4830 |
4833 double ext_root_time_ms = |
4831 double ext_root_time_sec = os::elapsedTime() - ext_roots_start - obj_copy_time_sec; |
4834 ((os::elapsedTime() - ext_roots_start) - obj_copy_time_sec) * 1000.0; |
4832 g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::ExtRootScan, worker_i, ext_root_time_sec); |
4835 |
|
4836 g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms); |
|
4837 |
4833 |
4838 // During conc marking we have to filter the per-thread SATB buffers |
4834 // During conc marking we have to filter the per-thread SATB buffers |
4839 // to make sure we remove any oops into the CSet (which will show up |
4835 // to make sure we remove any oops into the CSet (which will show up |
4840 // as implicitly live). |
4836 // as implicitly live). |
4841 double satb_filtering_ms = 0.0; |
4837 { |
4842 if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) { |
4838 G1GCParPhaseTimesTracker x(g1_policy()->phase_times(), G1GCPhaseTimes::SATBFiltering, worker_i); |
4843 if (mark_in_progress()) { |
4839 if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers) && mark_in_progress()) { |
4844 double satb_filter_start = os::elapsedTime(); |
|
4845 |
|
4846 JavaThread::satb_mark_queue_set().filter_thread_buffers(); |
4840 JavaThread::satb_mark_queue_set().filter_thread_buffers(); |
4847 |
4841 } |
4848 satb_filtering_ms = (os::elapsedTime() - satb_filter_start) * 1000.0; |
4842 } |
4849 } |
|
4850 } |
|
4851 g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms); |
|
4852 |
4843 |
4853 // Now scan the complement of the collection set. |
4844 // Now scan the complement of the collection set. |
4854 G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots); |
4845 G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots); |
4855 |
4846 |
4856 g1_rem_set()->oops_into_collection_set_do(scan_rs, &scavenge_cs_nmethods, worker_i); |
4847 g1_rem_set()->oops_into_collection_set_do(scan_rs, &scavenge_cs_nmethods, worker_i); |
5269 DirtyCardQueueSet* _queue; |
5260 DirtyCardQueueSet* _queue; |
5270 public: |
5261 public: |
5271 G1RedirtyLoggedCardsTask(DirtyCardQueueSet* queue) : AbstractGangTask("Redirty Cards"), _queue(queue) { } |
5262 G1RedirtyLoggedCardsTask(DirtyCardQueueSet* queue) : AbstractGangTask("Redirty Cards"), _queue(queue) { } |
5272 |
5263 |
5273 virtual void work(uint worker_id) { |
5264 virtual void work(uint worker_id) { |
5274 double start_time = os::elapsedTime(); |
5265 G1GCPhaseTimes* phase_times = G1CollectedHeap::heap()->g1_policy()->phase_times(); |
|
5266 G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::RedirtyCards, worker_id); |
5275 |
5267 |
5276 RedirtyLoggedCardTableEntryClosure cl; |
5268 RedirtyLoggedCardTableEntryClosure cl; |
5277 if (G1CollectedHeap::heap()->use_parallel_gc_threads()) { |
5269 if (G1CollectedHeap::heap()->use_parallel_gc_threads()) { |
5278 _queue->par_apply_closure_to_all_completed_buffers(&cl); |
5270 _queue->par_apply_closure_to_all_completed_buffers(&cl); |
5279 } else { |
5271 } else { |
5280 _queue->apply_closure_to_all_completed_buffers(&cl); |
5272 _queue->apply_closure_to_all_completed_buffers(&cl); |
5281 } |
5273 } |
5282 |
5274 |
5283 G1GCPhaseTimes* timer = G1CollectedHeap::heap()->g1_policy()->phase_times(); |
5275 phase_times->record_thread_work_item(G1GCPhaseTimes::RedirtyCards, worker_id, cl.num_processed()); |
5284 timer->record_redirty_logged_cards_time_ms(worker_id, (os::elapsedTime() - start_time) * 1000.0); |
|
5285 timer->record_redirty_logged_cards_processed_cards(worker_id, cl.num_processed()); |
|
5286 } |
5276 } |
5287 }; |
5277 }; |
5288 |
5278 |
5289 void G1CollectedHeap::redirty_logged_cards() { |
5279 void G1CollectedHeap::redirty_logged_cards() { |
5290 double redirty_logged_cards_start = os::elapsedTime(); |
5280 double redirty_logged_cards_start = os::elapsedTime(); |
5882 // elapsed time before closing the scope so that time |
5872 // elapsed time before closing the scope so that time |
5883 // taken for the SRS destructor is NOT included in the |
5873 // taken for the SRS destructor is NOT included in the |
5884 // reported parallel time. |
5874 // reported parallel time. |
5885 } |
5875 } |
5886 |
5876 |
|
5877 G1GCPhaseTimes* phase_times = g1_policy()->phase_times(); |
|
5878 |
5887 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; |
5879 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; |
5888 g1_policy()->phase_times()->record_par_time(par_time_ms); |
5880 phase_times->record_par_time(par_time_ms); |
5889 |
5881 |
5890 double code_root_fixup_time_ms = |
5882 double code_root_fixup_time_ms = |
5891 (os::elapsedTime() - end_par_time_sec) * 1000.0; |
5883 (os::elapsedTime() - end_par_time_sec) * 1000.0; |
5892 g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms); |
5884 phase_times->record_code_root_fixup_time(code_root_fixup_time_ms); |
5893 |
5885 |
5894 set_par_threads(0); |
5886 set_par_threads(0); |
5895 |
5887 |
5896 // Process any discovered reference objects - we have |
5888 // Process any discovered reference objects - we have |
5897 // to do this _before_ we retire the GC alloc regions |
5889 // to do this _before_ we retire the GC alloc regions |
5899 // objects (and their reachable sub-graphs) that were |
5891 // objects (and their reachable sub-graphs) that were |
5900 // not copied during the pause. |
5892 // not copied during the pause. |
5901 process_discovered_references(n_workers); |
5893 process_discovered_references(n_workers); |
5902 |
5894 |
5903 if (G1StringDedup::is_enabled()) { |
5895 if (G1StringDedup::is_enabled()) { |
|
5896 double fixup_start = os::elapsedTime(); |
|
5897 |
5904 G1STWIsAliveClosure is_alive(this); |
5898 G1STWIsAliveClosure is_alive(this); |
5905 G1KeepAliveClosure keep_alive(this); |
5899 G1KeepAliveClosure keep_alive(this); |
5906 G1StringDedup::unlink_or_oops_do(&is_alive, &keep_alive); |
5900 G1StringDedup::unlink_or_oops_do(&is_alive, &keep_alive, true, phase_times); |
|
5901 |
|
5902 double fixup_time_ms = (os::elapsedTime() - fixup_start) * 1000.0; |
|
5903 phase_times->record_string_dedup_fixup_time(fixup_time_ms); |
5907 } |
5904 } |
5908 |
5905 |
5909 _allocator->release_gc_alloc_regions(n_workers, evacuation_info); |
5906 _allocator->release_gc_alloc_regions(n_workers, evacuation_info); |
5910 g1_rem_set()->cleanup_after_oops_into_collection_set_do(); |
5907 g1_rem_set()->cleanup_after_oops_into_collection_set_do(); |
5911 |
5908 |