Mercurial > hg > graal-jvmci-8

comparison src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @ 23223:8f8f1d578796

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 8e83e6b768b8
children 79b13c9a93e8
comparison
equal deleted inserted replaced
23222:8e83e6b768b8 23223:8f8f1d578796
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
3899 3899
3900 _gc_tracer_stw->report_yc_type(yc_type()); 3900 _gc_tracer_stw->report_yc_type(yc_type());
3901 3901
3902 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); 3902 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
3903 3903
3904 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? 3904 uint active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
3905 workers()->active_workers() : 1); 3905 workers()->active_workers() : 1);
3906 double pause_start_sec = os::elapsedTime(); 3906 double pause_start_sec = os::elapsedTime();
3907 g1_policy()->phase_times()->note_gc_start(active_workers); 3907 g1_policy()->phase_times()->note_gc_start(active_workers, mark_in_progress());
3908 log_gc_header(); 3908 log_gc_header();
3909 3909
3910 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); 3910 TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
3911 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); 3911 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
3912 3912
4701 }; 4701 };
4702 4702
4703 void work(uint worker_id) { 4703 void work(uint worker_id) {
4704 if (worker_id >= _n_workers) return; // no work needed this round 4704 if (worker_id >= _n_workers) return; // no work needed this round
4705 4705
4706 double start_time_ms = os::elapsedTime() * 1000.0; 4706 _g1h->g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::GCWorkerStart, worker_id, os::elapsedTime());
4707 _g1h->g1_policy()->phase_times()->record_gc_worker_start_time(worker_id, start_time_ms);
4708 4707
4709 { 4708 {
4710 ResourceMark rm; 4709 ResourceMark rm;
4711 HandleMark hm; 4710 HandleMark hm;
4712 4711
4782 4781
4783 { 4782 {
4784 double start = os::elapsedTime(); 4783 double start = os::elapsedTime();
4785 G1ParEvacuateFollowersClosure evac(_g1h, &pss, _queues, &_terminator); 4784 G1ParEvacuateFollowersClosure evac(_g1h, &pss, _queues, &_terminator);
4786 evac.do_void(); 4785 evac.do_void();
4787 double elapsed_ms = (os::elapsedTime()-start)*1000.0; 4786 double elapsed_sec = os::elapsedTime() - start;
4788 double term_ms = pss.term_time()*1000.0; 4787 double term_sec = pss.term_time();
4789 _g1h->g1_policy()->phase_times()->add_obj_copy_time(worker_id, elapsed_ms-term_ms); 4788 _g1h->g1_policy()->phase_times()->add_time_secs(G1GCPhaseTimes::ObjCopy, worker_id, elapsed_sec - term_sec);
4790 _g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts()); 4789 _g1h->g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::Termination, worker_id, term_sec);
4790 _g1h->g1_policy()->phase_times()->record_thread_work_item(G1GCPhaseTimes::Termination, worker_id, pss.term_attempts());
4791 } 4791 }
4792 _g1h->g1_policy()->record_thread_age_table(pss.age_table()); 4792 _g1h->g1_policy()->record_thread_age_table(pss.age_table());
4793 _g1h->update_surviving_young_words(pss.surviving_young_words()+1); 4793 _g1h->update_surviving_young_words(pss.surviving_young_words()+1);
4794 4794
4795 if (ParallelGCVerbose) { 4795 if (ParallelGCVerbose) {
4801 4801
4802 // Close the inner scope so that the ResourceMark and HandleMark 4802 // Close the inner scope so that the ResourceMark and HandleMark
4803 // destructors are executed here and are included as part of the 4803 // destructors are executed here and are included as part of the
4804 // "GC Worker Time". 4804 // "GC Worker Time".
4805 } 4805 }
4806 4806 _g1h->g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::GCWorkerEnd, worker_id, os::elapsedTime());
4807 double end_time_ms = os::elapsedTime() * 1000.0;
4808 _g1h->g1_policy()->phase_times()->record_gc_worker_end_time(worker_id, end_time_ms);
4809 } 4807 }
4810 }; 4808 };
4811 4809
4812 // *** Common G1 Evacuation Stuff 4810 // *** Common G1 Evacuation Stuff
4813 4811
4865 buf_scan_non_heap_weak_roots.done(); 4863 buf_scan_non_heap_weak_roots.done();
4866 4864
4867 double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds() 4865 double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds()
4868 + buf_scan_non_heap_weak_roots.closure_app_seconds(); 4866 + buf_scan_non_heap_weak_roots.closure_app_seconds();
4869 4867
4870 g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); 4868 g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::ObjCopy, worker_i, obj_copy_time_sec);
4871 4869
4872 double ext_root_time_ms = 4870 double ext_root_time_sec = os::elapsedTime() - ext_roots_start - obj_copy_time_sec;
4873 ((os::elapsedTime() - ext_roots_start) - obj_copy_time_sec) * 1000.0; 4871 g1_policy()->phase_times()->record_time_secs(G1GCPhaseTimes::ExtRootScan, worker_i, ext_root_time_sec);
4874
4875 g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
4876 4872
4877 // During conc marking we have to filter the per-thread SATB buffers 4873 // During conc marking we have to filter the per-thread SATB buffers
4878 // to make sure we remove any oops into the CSet (which will show up 4874 // to make sure we remove any oops into the CSet (which will show up
4879 // as implicitly live). 4875 // as implicitly live).
4880 double satb_filtering_ms = 0.0; 4876 {
4881 if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) { 4877 G1GCParPhaseTimesTracker x(g1_policy()->phase_times(), G1GCPhaseTimes::SATBFiltering, worker_i);
4882 if (mark_in_progress()) { 4878 if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers) && mark_in_progress()) {
4883 double satb_filter_start = os::elapsedTime();
4884
4885 JavaThread::satb_mark_queue_set().filter_thread_buffers(); 4879 JavaThread::satb_mark_queue_set().filter_thread_buffers();
4886 4880 }
4887 satb_filtering_ms = (os::elapsedTime() - satb_filter_start) * 1000.0; 4881 }
4888 }
4889 }
4890 g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms);
4891 4882
4892 // Now scan the complement of the collection set. 4883 // Now scan the complement of the collection set.
4893 G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots); 4884 G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots);
4894 4885
4895 g1_rem_set()->oops_into_collection_set_do(scan_rs, &scavenge_cs_nmethods, worker_i); 4886 g1_rem_set()->oops_into_collection_set_do(scan_rs, &scavenge_cs_nmethods, worker_i);
5308 DirtyCardQueueSet* _queue; 5299 DirtyCardQueueSet* _queue;
5309 public: 5300 public:
5310 G1RedirtyLoggedCardsTask(DirtyCardQueueSet* queue) : AbstractGangTask("Redirty Cards"), _queue(queue) { } 5301 G1RedirtyLoggedCardsTask(DirtyCardQueueSet* queue) : AbstractGangTask("Redirty Cards"), _queue(queue) { }
5311 5302
5312 virtual void work(uint worker_id) { 5303 virtual void work(uint worker_id) {
5313 double start_time = os::elapsedTime(); 5304 G1GCPhaseTimes* phase_times = G1CollectedHeap::heap()->g1_policy()->phase_times();
5305 G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::RedirtyCards, worker_id);
5314 5306
5315 RedirtyLoggedCardTableEntryClosure cl; 5307 RedirtyLoggedCardTableEntryClosure cl;
5316 if (G1CollectedHeap::heap()->use_parallel_gc_threads()) { 5308 if (G1CollectedHeap::heap()->use_parallel_gc_threads()) {
5317 _queue->par_apply_closure_to_all_completed_buffers(&cl); 5309 _queue->par_apply_closure_to_all_completed_buffers(&cl);
5318 } else { 5310 } else {
5319 _queue->apply_closure_to_all_completed_buffers(&cl); 5311 _queue->apply_closure_to_all_completed_buffers(&cl);
5320 } 5312 }
5321 5313
5322 G1GCPhaseTimes* timer = G1CollectedHeap::heap()->g1_policy()->phase_times(); 5314 phase_times->record_thread_work_item(G1GCPhaseTimes::RedirtyCards, worker_id, cl.num_processed());
5323 timer->record_redirty_logged_cards_time_ms(worker_id, (os::elapsedTime() - start_time) * 1000.0);
5324 timer->record_redirty_logged_cards_processed_cards(worker_id, cl.num_processed());
5325 } 5315 }
5326 }; 5316 };
5327 5317
5328 void G1CollectedHeap::redirty_logged_cards() { 5318 void G1CollectedHeap::redirty_logged_cards() {
5329 double redirty_logged_cards_start = os::elapsedTime(); 5319 double redirty_logged_cards_start = os::elapsedTime();
5921 // elapsed time before closing the scope so that time 5911 // elapsed time before closing the scope so that time
5922 // taken for the SRS destructor is NOT included in the 5912 // taken for the SRS destructor is NOT included in the
5923 // reported parallel time. 5913 // reported parallel time.
5924 } 5914 }
5925 5915
5916 G1GCPhaseTimes* phase_times = g1_policy()->phase_times();
5917
5926 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; 5918 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0;
5927 g1_policy()->phase_times()->record_par_time(par_time_ms); 5919 phase_times->record_par_time(par_time_ms);
5928 5920
5929 double code_root_fixup_time_ms = 5921 double code_root_fixup_time_ms =
5930 (os::elapsedTime() - end_par_time_sec) * 1000.0; 5922 (os::elapsedTime() - end_par_time_sec) * 1000.0;
5931 g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms); 5923 phase_times->record_code_root_fixup_time(code_root_fixup_time_ms);
5932 5924
5933 set_par_threads(0); 5925 set_par_threads(0);
5934 5926
5935 // Process any discovered reference objects - we have 5927 // Process any discovered reference objects - we have
5936 // to do this _before_ we retire the GC alloc regions 5928 // to do this _before_ we retire the GC alloc regions
5938 // objects (and their reachable sub-graphs) that were 5930 // objects (and their reachable sub-graphs) that were
5939 // not copied during the pause. 5931 // not copied during the pause.
5940 process_discovered_references(n_workers); 5932 process_discovered_references(n_workers);
5941 5933
5942 if (G1StringDedup::is_enabled()) { 5934 if (G1StringDedup::is_enabled()) {
5935 double fixup_start = os::elapsedTime();
5936
5943 G1STWIsAliveClosure is_alive(this); 5937 G1STWIsAliveClosure is_alive(this);
5944 G1KeepAliveClosure keep_alive(this); 5938 G1KeepAliveClosure keep_alive(this);
5945 G1StringDedup::unlink_or_oops_do(&is_alive, &keep_alive); 5939 G1StringDedup::unlink_or_oops_do(&is_alive, &keep_alive, true, phase_times);
5940
5941 double fixup_time_ms = (os::elapsedTime() - fixup_start) * 1000.0;
5942 phase_times->record_string_dedup_fixup_time(fixup_time_ms);
5946 } 5943 }
5947 5944
5948 _allocator->release_gc_alloc_regions(n_workers, evacuation_info); 5945 _allocator->release_gc_alloc_regions(n_workers, evacuation_info);
5949 g1_rem_set()->cleanup_after_oops_into_collection_set_do(); 5946 g1_rem_set()->cleanup_after_oops_into_collection_set_do();
5950 5947