1122 } |
1121 } |
1123 |
1122 |
1124 // Anything below that is considered to be zero |
1123 // Anything below that is considered to be zero |
1125 #define MIN_TIMER_GRANULARITY 0.0000001 |
1124 #define MIN_TIMER_GRANULARITY 0.0000001 |
1126 |
1125 |
1127 void G1CollectorPolicy::record_collection_pause_end(bool abandoned) { |
1126 void G1CollectorPolicy::record_collection_pause_end() { |
1128 double end_time_sec = os::elapsedTime(); |
1127 double end_time_sec = os::elapsedTime(); |
1129 double elapsed_ms = _last_pause_time_ms; |
1128 double elapsed_ms = _last_pause_time_ms; |
1130 bool parallel = ParallelGCThreads > 0; |
1129 bool parallel = ParallelGCThreads > 0; |
1131 double evac_ms = (end_time_sec - _cur_G1_strong_roots_end_sec) * 1000.0; |
1130 double evac_ms = (end_time_sec - _cur_G1_strong_roots_end_sec) * 1000.0; |
1132 size_t rs_size = |
1131 size_t rs_size = |
1133 _cur_collection_pause_used_regions_at_start - collection_set_size(); |
1132 _cur_collection_pause_used_regions_at_start - collection_set_size(); |
1134 size_t cur_used_bytes = _g1->used(); |
1133 size_t cur_used_bytes = _g1->used(); |
1135 assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); |
1134 assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); |
1136 bool last_pause_included_initial_mark = false; |
1135 bool last_pause_included_initial_mark = false; |
1137 bool update_stats = !abandoned && !_g1->evacuation_failed(); |
1136 bool update_stats = !_g1->evacuation_failed(); |
1138 |
1137 |
1139 #ifndef PRODUCT |
1138 #ifndef PRODUCT |
1140 if (G1YoungSurvRateVerbose) { |
1139 if (G1YoungSurvRateVerbose) { |
1141 gclog_or_tty->print_cr(""); |
1140 gclog_or_tty->print_cr(""); |
1142 _short_lived_surv_rate_group->print(); |
1141 _short_lived_surv_rate_group->print(); |
1344 recent_avg_pause_time_ratio() * 100.0); |
1338 recent_avg_pause_time_ratio() * 100.0); |
1345 } |
1339 } |
1346 |
1340 |
1347 double other_time_ms = elapsed_ms; |
1341 double other_time_ms = elapsed_ms; |
1348 |
1342 |
1349 if (!abandoned) { |
1343 if (_satb_drain_time_set) { |
1350 if (_satb_drain_time_set) |
1344 other_time_ms -= _cur_satb_drain_time_ms; |
1351 other_time_ms -= _cur_satb_drain_time_ms; |
1345 } |
1352 |
1346 |
1353 if (parallel) |
1347 if (parallel) { |
1354 other_time_ms -= _cur_collection_par_time_ms + _cur_clear_ct_time_ms; |
1348 other_time_ms -= _cur_collection_par_time_ms + _cur_clear_ct_time_ms; |
1355 else |
1349 } else { |
1356 other_time_ms -= |
1350 other_time_ms -= |
1357 update_rs_time + |
1351 update_rs_time + |
1358 ext_root_scan_time + mark_stack_scan_time + |
1352 ext_root_scan_time + mark_stack_scan_time + |
1359 scan_rs_time + obj_copy_time; |
1353 scan_rs_time + obj_copy_time; |
1360 } |
1354 } |
1361 |
1355 |
1362 if (PrintGCDetails) { |
1356 if (PrintGCDetails) { |
1363 gclog_or_tty->print_cr("%s%s, %1.8lf secs]", |
1357 gclog_or_tty->print_cr("%s, %1.8lf secs]", |
1364 abandoned ? " (abandoned)" : "", |
|
1365 (last_pause_included_initial_mark) ? " (initial-mark)" : "", |
1358 (last_pause_included_initial_mark) ? " (initial-mark)" : "", |
1366 elapsed_ms / 1000.0); |
1359 elapsed_ms / 1000.0); |
1367 |
1360 |
1368 if (!abandoned) { |
1361 if (_satb_drain_time_set) { |
1369 if (_satb_drain_time_set) { |
1362 print_stats(1, "SATB Drain Time", _cur_satb_drain_time_ms); |
1370 print_stats(1, "SATB Drain Time", _cur_satb_drain_time_ms); |
1363 } |
1371 } |
1364 if (_last_satb_drain_processed_buffers >= 0) { |
1372 if (_last_satb_drain_processed_buffers >= 0) { |
1365 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers); |
1373 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers); |
1366 } |
1374 } |
1367 if (parallel) { |
1375 if (parallel) { |
1368 print_stats(1, "Parallel Time", _cur_collection_par_time_ms); |
1376 print_stats(1, "Parallel Time", _cur_collection_par_time_ms); |
1369 print_par_stats(2, "GC Worker Start Time", |
1377 print_par_stats(2, "GC Worker Start Time", |
1370 _par_last_gc_worker_start_times_ms, false); |
1378 _par_last_gc_worker_start_times_ms, false); |
1371 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); |
1379 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); |
1372 print_par_sizes(3, "Processed Buffers", |
1380 print_par_sizes(3, "Processed Buffers", |
1373 _par_last_update_rs_processed_buffers, true); |
1381 _par_last_update_rs_processed_buffers, true); |
1374 print_par_stats(2, "Ext Root Scanning", |
1382 print_par_stats(2, "Ext Root Scanning", |
1375 _par_last_ext_root_scan_times_ms); |
1383 _par_last_ext_root_scan_times_ms); |
1376 print_par_stats(2, "Mark Stack Scanning", |
1384 print_par_stats(2, "Mark Stack Scanning", |
1377 _par_last_mark_stack_scan_times_ms); |
1385 _par_last_mark_stack_scan_times_ms); |
1378 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); |
1386 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); |
1379 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); |
1387 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); |
1380 print_par_stats(2, "Termination", _par_last_termination_times_ms); |
1388 print_par_stats(2, "Termination", _par_last_termination_times_ms); |
1381 print_par_sizes(3, "Termination Attempts", |
1389 print_par_sizes(3, "Termination Attempts", |
1382 _par_last_termination_attempts, true); |
1390 _par_last_termination_attempts, true); |
1383 print_par_stats(2, "GC Worker End Time", |
1391 print_par_stats(2, "GC Worker End Time", |
1384 _par_last_gc_worker_end_times_ms, false); |
1392 _par_last_gc_worker_end_times_ms, false); |
1385 print_stats(2, "Other", parallel_other_time); |
1393 print_stats(2, "Other", parallel_other_time); |
1386 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); |
1394 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); |
1387 } else { |
1395 } else { |
1388 print_stats(1, "Update RS", update_rs_time); |
1396 print_stats(1, "Update RS", update_rs_time); |
1389 print_stats(2, "Processed Buffers", |
1397 print_stats(2, "Processed Buffers", |
1390 (int)update_rs_processed_buffers); |
1398 (int)update_rs_processed_buffers); |
1391 print_stats(1, "Ext Root Scanning", ext_root_scan_time); |
1399 print_stats(1, "Ext Root Scanning", ext_root_scan_time); |
1392 print_stats(1, "Mark Stack Scanning", mark_stack_scan_time); |
1400 print_stats(1, "Mark Stack Scanning", mark_stack_scan_time); |
1393 print_stats(1, "Scan RS", scan_rs_time); |
1401 print_stats(1, "Scan RS", scan_rs_time); |
1394 print_stats(1, "Object Copying", obj_copy_time); |
1402 print_stats(1, "Object Copying", obj_copy_time); |
|
1403 } |
|
1404 } |
1395 } |
1405 #ifndef PRODUCT |
1396 #ifndef PRODUCT |
1406 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); |
1397 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); |
1407 print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms); |
1398 print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms); |
1408 print_stats(1, "Min Clear CC", _min_clear_cc_time_ms); |
1399 print_stats(1, "Min Clear CC", _min_clear_cc_time_ms); |
2174 } |
2165 } |
2175 } |
2166 } |
2176 print_summary(1, "Other", summary->get_other_seq()); |
2167 print_summary(1, "Other", summary->get_other_seq()); |
2177 { |
2168 { |
2178 NumberSeq calc_other_times_ms; |
2169 NumberSeq calc_other_times_ms; |
2179 if (body_summary != NULL) { |
2170 if (parallel) { |
2180 // not abandoned |
2171 // parallel |
2181 if (parallel) { |
2172 NumberSeq* other_parts[] = { |
2182 // parallel |
2173 body_summary->get_satb_drain_seq(), |
2183 NumberSeq* other_parts[] = { |
2174 body_summary->get_parallel_seq(), |
2184 body_summary->get_satb_drain_seq(), |
2175 body_summary->get_clear_ct_seq() |
2185 body_summary->get_parallel_seq(), |
2176 }; |
2186 body_summary->get_clear_ct_seq() |
2177 calc_other_times_ms = NumberSeq(summary->get_total_seq(), |
2187 }; |
2178 3, other_parts); |
2188 calc_other_times_ms = NumberSeq(summary->get_total_seq(), |
|
2189 3, other_parts); |
|
2190 } else { |
|
2191 // serial |
|
2192 NumberSeq* other_parts[] = { |
|
2193 body_summary->get_satb_drain_seq(), |
|
2194 body_summary->get_update_rs_seq(), |
|
2195 body_summary->get_ext_root_scan_seq(), |
|
2196 body_summary->get_mark_stack_scan_seq(), |
|
2197 body_summary->get_scan_rs_seq(), |
|
2198 body_summary->get_obj_copy_seq() |
|
2199 }; |
|
2200 calc_other_times_ms = NumberSeq(summary->get_total_seq(), |
|
2201 7, other_parts); |
|
2202 } |
|
2203 } else { |
2179 } else { |
2204 // abandoned |
2180 // serial |
2205 calc_other_times_ms = NumberSeq(); |
2181 NumberSeq* other_parts[] = { |
|
2182 body_summary->get_satb_drain_seq(), |
|
2183 body_summary->get_update_rs_seq(), |
|
2184 body_summary->get_ext_root_scan_seq(), |
|
2185 body_summary->get_mark_stack_scan_seq(), |
|
2186 body_summary->get_scan_rs_seq(), |
|
2187 body_summary->get_obj_copy_seq() |
|
2188 }; |
|
2189 calc_other_times_ms = NumberSeq(summary->get_total_seq(), |
|
2190 7, other_parts); |
2206 } |
2191 } |
2207 check_other_times(1, summary->get_other_seq(), &calc_other_times_ms); |
2192 check_other_times(1, summary->get_other_seq(), &calc_other_times_ms); |
2208 } |
2193 } |
2209 } else { |
2194 } else { |
2210 print_indent(0); |
2195 print_indent(0); |
2211 gclog_or_tty->print_cr("none"); |
2196 gclog_or_tty->print_cr("none"); |
2212 } |
2197 } |
2213 gclog_or_tty->print_cr(""); |
2198 gclog_or_tty->print_cr(""); |
2214 } |
|
2215 |
|
2216 void |
|
2217 G1CollectorPolicy::print_abandoned_summary(PauseSummary* summary) const { |
|
2218 bool printed = false; |
|
2219 if (summary->get_total_seq()->num() > 0) { |
|
2220 printed = true; |
|
2221 print_summary(summary); |
|
2222 } |
|
2223 if (!printed) { |
|
2224 print_indent(0); |
|
2225 gclog_or_tty->print_cr("none"); |
|
2226 gclog_or_tty->print_cr(""); |
|
2227 } |
|
2228 } |
2199 } |
2229 |
2200 |
2230 void G1CollectorPolicy::print_tracing_info() const { |
2201 void G1CollectorPolicy::print_tracing_info() const { |
2231 if (TraceGen0Time) { |
2202 if (TraceGen0Time) { |
2232 gclog_or_tty->print_cr("ALL PAUSES"); |
2203 gclog_or_tty->print_cr("ALL PAUSES"); |
3055 end_recording_regions(); |
3002 end_recording_regions(); |
3056 |
3003 |
3057 double non_young_end_time_sec = os::elapsedTime(); |
3004 double non_young_end_time_sec = os::elapsedTime(); |
3058 _recorded_non_young_cset_choice_time_ms = |
3005 _recorded_non_young_cset_choice_time_ms = |
3059 (non_young_end_time_sec - non_young_start_time_sec) * 1000.0; |
3006 (non_young_end_time_sec - non_young_start_time_sec) * 1000.0; |
3060 |
|
3061 // Here we are supposed to return whether the pause should be |
|
3062 // abandoned or not (i.e., whether the collection set is empty or |
|
3063 // not). However, this introduces a subtle issue when a pause is |
|
3064 // initiated explicitly with System.gc() and |
|
3065 // +ExplicitGCInvokesConcurrent (see Comment #2 in CR 6944166), it's |
|
3066 // supposed to start a marking cycle, and it's abandoned. So, by |
|
3067 // returning false here we are telling the caller never to consider |
|
3068 // a pause to be abandoned. We'll actually remove all the code |
|
3069 // associated with abandoned pauses as part of CR 6963209, but we are |
|
3070 // just disabling them this way for the moment to avoid increasing |
|
3071 // further the amount of changes for CR 6944166. |
|
3072 return false; |
|
3073 } |
3007 } |
3074 |
3008 |
3075 void G1CollectorPolicy_BestRegionsFirst::record_full_collection_end() { |
3009 void G1CollectorPolicy_BestRegionsFirst::record_full_collection_end() { |
3076 G1CollectorPolicy::record_full_collection_end(); |
3010 G1CollectorPolicy::record_full_collection_end(); |
3077 _collectionSetChooser->updateAfterFullCollection(); |
3011 _collectionSetChooser->updateAfterFullCollection(); |