1.1 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Fri Jul 13 14:16:21 2012 -0700
1.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Jul 16 13:00:26 2012 -0700
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
