1.1 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Jul 02 10:54:17 2012 -0400 1.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Wed Jul 11 22:47:38 2012 +0200 1.3 @@ -33,6 +33,7 @@ 1.4 #include "gc_implementation/g1/g1CollectorPolicy.hpp" 1.5 #include "gc_implementation/g1/g1ErgoVerbose.hpp" 1.6 #include "gc_implementation/g1/g1EvacFailure.hpp" 1.7 +#include "gc_implementation/g1/g1GCPhaseTimes.hpp" 1.8 #include "gc_implementation/g1/g1Log.hpp" 1.9 #include "gc_implementation/g1/g1MarkSweep.hpp" 1.10 #include "gc_implementation/g1/g1OopClosures.inline.hpp" 1.11 @@ -2274,7 +2275,7 @@ 1.12 while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) { 1.13 n_completed_buffers++; 1.14 } 1.15 - g1_policy()->record_update_rs_processed_buffers(worker_i, 1.16 + g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i, 1.17 (double) n_completed_buffers); 1.18 dcqs.clear_n_completed_buffers(); 1.19 assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); 1.20 @@ -3633,10 +3634,10 @@ 1.21 gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); 1.22 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); 1.23 1.24 - GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) 1.25 - .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") 1.26 - .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); 1.27 - TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty); 1.28 + int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? 1.29 + workers()->active_workers() : 1); 1.30 + g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers, 1.31 + g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause()); 1.32 1.33 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); 1.34 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); 1.35 @@ -3699,9 +3700,15 @@ 1.36 // before the start GC event. 1.37 _hr_printer.start_gc(false /* full */, (size_t) total_collections()); 1.38 1.39 + // This timing is only used by the ergonomics to handle our pause target. 1.40 + // It is unclear why this should not include the full pause. We will 1.41 + // investigate this in CR 7178365. 1.42 + // 1.43 + // Preserving the old comment here if that helps the investigation: 1.44 + // 1.45 // The elapsed time induced by the start time below deliberately elides 1.46 // the possible verification above. 1.47 - double start_time_sec = os::elapsedTime(); 1.48 + double sample_start_time_sec = os::elapsedTime(); 1.49 size_t start_used_bytes = used(); 1.50 1.51 #if YOUNG_LIST_VERBOSE 1.52 @@ -3710,7 +3717,7 @@ 1.53 g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty); 1.54 #endif // YOUNG_LIST_VERBOSE 1.55 1.56 - g1_policy()->record_collection_pause_start(start_time_sec, 1.57 + g1_policy()->record_collection_pause_start(sample_start_time_sec, 1.58 start_used_bytes); 1.59 1.60 double scan_wait_start = os::elapsedTime(); 1.61 @@ -3719,11 +3726,12 @@ 1.62 // objects on them have been correctly scanned before we start 1.63 // moving them during the GC. 1.64 bool waited = _cm->root_regions()->wait_until_scan_finished(); 1.65 + double wait_time_ms = 0.0; 1.66 if (waited) { 1.67 double scan_wait_end = os::elapsedTime(); 1.68 - double wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; 1.69 - g1_policy()->record_root_region_scan_wait_time(wait_time_ms); 1.70 + wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; 1.71 } 1.72 + g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms); 1.73 1.74 #if YOUNG_LIST_VERBOSE 1.75 gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:"); 1.76 @@ -3877,12 +3885,16 @@ 1.77 true /* verify_fingers */); 1.78 _cm->note_end_of_gc(); 1.79 1.80 - double end_time_sec = os::elapsedTime(); 1.81 - double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS; 1.82 - g1_policy()->record_pause_time_ms(pause_time_ms); 1.83 - int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? 1.84 - workers()->active_workers() : 1); 1.85 - g1_policy()->record_collection_pause_end(active_workers); 1.86 + // Collect thread local data to allow the ergonomics to use 1.87 + // the collected information 1.88 + g1_policy()->phase_times()->collapse_par_times(); 1.89 + 1.90 + // This timing is only used by the ergonomics to handle our pause target. 1.91 + // It is unclear why this should not include the full pause. We will 1.92 + // investigate this in CR 7178365. 1.93 + double sample_end_time_sec = os::elapsedTime(); 1.94 + double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS; 1.95 + g1_policy()->record_collection_pause_end(pause_time_ms); 1.96 1.97 MemoryService::track_memory_usage(); 1.98 1.99 @@ -3929,9 +3941,6 @@ 1.100 // RETIRE events are generated before the end GC event. 1.101 _hr_printer.end_gc(false /* full */, (size_t) total_collections()); 1.102 1.103 - // We have to do this after we decide whether to expand the heap or not. 1.104 - g1_policy()->print_heap_transition(); 1.105 - 1.106 if (mark_in_progress()) { 1.107 concurrent_mark()->update_g1_committed(); 1.108 } 1.109 @@ -3941,13 +3950,14 @@ 1.110 #endif 1.111 1.112 gc_epilogue(false); 1.113 + 1.114 + g1_policy()->phase_times()->note_gc_end(os::elapsedTime()); 1.115 + 1.116 + // We have to do this after we decide whether to expand the heap or not. 1.117 + g1_policy()->print_heap_transition(); 1.118 } 1.119 1.120 - // The closing of the inner scope, immediately above, will complete 1.121 - // logging at the "fine" level. The record_collection_pause_end() call 1.122 - // above will complete logging at the "finer" level. 1.123 - // 1.124 - // It is not yet to safe, however, to tell the concurrent mark to 1.125 + // It is not yet to safe to tell the concurrent mark to 1.126 // start as we have some optional output below. We don't want the 1.127 // output from the concurrent mark thread interfering with this 1.128 // logging output either. 1.129 @@ -4695,7 +4705,7 @@ 1.130 if (worker_id >= _n_workers) return; // no work needed this round 1.131 1.132 double start_time_ms = os::elapsedTime() * 1000.0; 1.133 - _g1h->g1_policy()->record_gc_worker_start_time(worker_id, start_time_ms); 1.134 + _g1h->g1_policy()->phase_times()->record_gc_worker_start_time(worker_id, start_time_ms); 1.135 1.136 { 1.137 ResourceMark rm; 1.138 @@ -4744,8 +4754,8 @@ 1.139 evac.do_void(); 1.140 double elapsed_ms = (os::elapsedTime()-start)*1000.0; 1.141 double term_ms = pss.term_time()*1000.0; 1.142 - _g1h->g1_policy()->record_obj_copy_time(worker_id, elapsed_ms-term_ms); 1.143 - _g1h->g1_policy()->record_termination(worker_id, term_ms, pss.term_attempts()); 1.144 + _g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms); 1.145 + _g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts()); 1.146 } 1.147 _g1h->g1_policy()->record_thread_age_table(pss.age_table()); 1.148 _g1h->update_surviving_young_words(pss.surviving_young_words()+1); 1.149 @@ -4763,7 +4773,7 @@ 1.150 } 1.151 1.152 double end_time_ms = os::elapsedTime() * 1000.0; 1.153 - _g1h->g1_policy()->record_gc_worker_end_time(worker_id, end_time_ms); 1.154 + _g1h->g1_policy()->phase_times()->record_gc_worker_end_time(worker_id, end_time_ms); 1.155 } 1.156 }; 1.157 1.158 @@ -4874,15 +4884,15 @@ 1.159 1.160 double ext_roots_end = os::elapsedTime(); 1.161 1.162 - g1_policy()->reset_obj_copy_time(worker_i); 1.163 + g1_policy()->phase_times()->reset_obj_copy_time(worker_i); 1.164 double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() + 1.165 buf_scan_non_heap_roots.closure_app_seconds(); 1.166 - g1_policy()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); 1.167 + g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); 1.168 1.169 double ext_root_time_ms = 1.170 ((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0; 1.171 1.172 - g1_policy()->record_ext_root_scan_time(worker_i, ext_root_time_ms); 1.173 + g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms); 1.174 1.175 // During conc marking we have to filter the per-thread SATB buffers 1.176 // to make sure we remove any oops into the CSet (which will show up 1.177 @@ -4893,7 +4903,7 @@ 1.178 } 1.179 } 1.180 double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0; 1.181 - g1_policy()->record_satb_filtering_time(worker_i, satb_filtering_ms); 1.182 + g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms); 1.183 1.184 // Now scan the complement of the collection set. 1.185 if (scan_rs != NULL) { 1.186 @@ -5393,7 +5403,7 @@ 1.187 assert(pss.refs()->is_empty(), "both queue and overflow should be empty"); 1.188 1.189 double ref_proc_time = os::elapsedTime() - ref_proc_start; 1.190 - g1_policy()->record_ref_proc_time(ref_proc_time * 1000.0); 1.191 + g1_policy()->phase_times()->record_ref_proc_time(ref_proc_time * 1000.0); 1.192 } 1.193 1.194 // Weak Reference processing during an evacuation pause (part 2). 1.195 @@ -5430,7 +5440,7 @@ 1.196 // and could signicantly increase the pause time. 1.197 1.198 double ref_enq_time = os::elapsedTime() - ref_enq_start; 1.199 - g1_policy()->record_ref_enq_time(ref_enq_time * 1000.0); 1.200 + g1_policy()->phase_times()->record_ref_enq_time(ref_enq_time * 1000.0); 1.201 } 1.202 1.203 void G1CollectedHeap::evacuate_collection_set() { 1.204 @@ -5493,11 +5503,11 @@ 1.205 } 1.206 1.207 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; 1.208 - g1_policy()->record_par_time(par_time_ms); 1.209 + g1_policy()->phase_times()->record_par_time(par_time_ms); 1.210 1.211 double code_root_fixup_time_ms = 1.212 (os::elapsedTime() - end_par_time_sec) * 1000.0; 1.213 - g1_policy()->record_code_root_fixup_time(code_root_fixup_time_ms); 1.214 + g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms); 1.215 1.216 set_par_threads(0); 1.217 1.218 @@ -5759,7 +5769,7 @@ 1.219 } 1.220 1.221 double elapsed = os::elapsedTime() - start; 1.222 - g1_policy()->record_clear_ct_time(elapsed * 1000.0); 1.223 + g1_policy()->phase_times()->record_clear_ct_time(elapsed * 1000.0); 1.224 } 1.225 1.226 void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) { 1.227 @@ -5868,8 +5878,8 @@ 1.228 NULL /* old_proxy_set */, 1.229 NULL /* humongous_proxy_set */, 1.230 false /* par */); 1.231 - policy->record_young_free_cset_time_ms(young_time_ms); 1.232 - policy->record_non_young_free_cset_time_ms(non_young_time_ms); 1.233 + policy->phase_times()->record_young_free_cset_time_ms(young_time_ms); 1.234 + policy->phase_times()->record_non_young_free_cset_time_ms(non_young_time_ms); 1.235 } 1.236 1.237 // This routine is similar to the above but does not record