Mercurial > hg > graal-jvmci-8

comparison src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @ 22908:c3fcc09c9239

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases Reviewed-by: tschatzl, mgerdin, ecaspole
author brutisso
date Thu, 26 Mar 2015 13:19:32 +0100
parents 93a69595b807
children 38d6febe66af
comparison
equal deleted inserted replaced
22907:93a69595b807 22908:c3fcc09c9239
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
4662 }; 4662 };
4663 4663
4664 void work(uint worker_id) { 4664 void work(uint worker_id) {
4665 if (worker_id >= _n_workers) return; // no work needed this round 4665 if (worker_id >= _n_workers) return; // no work needed this round
4666 4666
4667 double start_time_ms = os::elapsedTime() * 1000.0; 4667 _g1h->g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::GCWorkerStart, worker_id, os::elapsedTime());
4668 _g1h->g1_policy()->phase_times()->record_gc_worker_start_time(worker_id, start_time_ms);
4669 4668
4670 { 4669 {
4671 ResourceMark rm; 4670 ResourceMark rm;
4672 HandleMark hm; 4671 HandleMark hm;
4673 4672
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