Mercurial > hg > graal-compiler
comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 3823:14a2fd14c0db
7068240: G1: Long "parallel other time" and "ext root scanning" when running specific benchmark
Summary: In root processing, move the scanning of the reference processor's discovered lists to before RSet updating and scanning. When scanning the reference processor's discovered lists, use a buffering closure so that the time spent copying any reference object is correctly attributed. Also removed a couple of unused and irrelevant timers.
Reviewed-by: ysr, jmasa
author | johnc |
---|---|
date | Mon, 01 Aug 2011 10:04:28 -0700 |
parents | 5f6f2615433a |
children | f44782f04dd4 |
comparison
equal
deleted
inserted
replaced
3821:8107273fd204 | 3823:14a2fd14c0db |
---|---|
132 } | 132 } |
133 }; | 133 }; |
134 | 134 |
135 G1CollectorPolicy::G1CollectorPolicy() : | 135 G1CollectorPolicy::G1CollectorPolicy() : |
136 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() | 136 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() |
137 ? ParallelGCThreads : 1), | 137 ? ParallelGCThreads : 1), |
138 | |
139 | 138 |
140 _n_pauses(0), | 139 _n_pauses(0), |
141 _recent_CH_strong_roots_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), | 140 _recent_rs_scan_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), |
142 _recent_G1_strong_roots_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), | |
143 _recent_evac_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), | |
144 _recent_pause_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), | 141 _recent_pause_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), |
145 _recent_rs_sizes(new TruncatedSeq(NumPrevPausesForHeuristics)), | 142 _recent_rs_sizes(new TruncatedSeq(NumPrevPausesForHeuristics)), |
146 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), | 143 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), |
147 _all_pause_times_ms(new NumberSeq()), | 144 _all_pause_times_ms(new NumberSeq()), |
148 _stop_world_start(0.0), | 145 _stop_world_start(0.0), |
1048 } | 1045 } |
1049 | 1046 |
1050 void G1CollectorPolicy::record_concurrent_pause_end() { | 1047 void G1CollectorPolicy::record_concurrent_pause_end() { |
1051 } | 1048 } |
1052 | 1049 |
1053 void G1CollectorPolicy::record_collection_pause_end_CH_strong_roots() { | |
1054 _cur_CH_strong_roots_end_sec = os::elapsedTime(); | |
1055 _cur_CH_strong_roots_dur_ms = | |
1056 (_cur_CH_strong_roots_end_sec - _cur_collection_start_sec) * 1000.0; | |
1057 } | |
1058 | |
1059 void G1CollectorPolicy::record_collection_pause_end_G1_strong_roots() { | |
1060 _cur_G1_strong_roots_end_sec = os::elapsedTime(); | |
1061 _cur_G1_strong_roots_dur_ms = | |
1062 (_cur_G1_strong_roots_end_sec - _cur_CH_strong_roots_end_sec) * 1000.0; | |
1063 } | |
1064 | |
1065 template<class T> | 1050 template<class T> |
1066 T sum_of(T* sum_arr, int start, int n, int N) { | 1051 T sum_of(T* sum_arr, int start, int n, int N) { |
1067 T sum = (T)0; | 1052 T sum = (T)0; |
1068 for (int i = 0; i < n; i++) { | 1053 for (int i = 0; i < n; i++) { |
1069 int j = (start + i) % N; | 1054 int j = (start + i) % N; |
1181 | 1166 |
1182 void G1CollectorPolicy::record_collection_pause_end() { | 1167 void G1CollectorPolicy::record_collection_pause_end() { |
1183 double end_time_sec = os::elapsedTime(); | 1168 double end_time_sec = os::elapsedTime(); |
1184 double elapsed_ms = _last_pause_time_ms; | 1169 double elapsed_ms = _last_pause_time_ms; |
1185 bool parallel = G1CollectedHeap::use_parallel_gc_threads(); | 1170 bool parallel = G1CollectedHeap::use_parallel_gc_threads(); |
1186 double evac_ms = (end_time_sec - _cur_G1_strong_roots_end_sec) * 1000.0; | |
1187 size_t rs_size = | 1171 size_t rs_size = |
1188 _cur_collection_pause_used_regions_at_start - collection_set_size(); | 1172 _cur_collection_pause_used_regions_at_start - collection_set_size(); |
1189 size_t cur_used_bytes = _g1->used(); | 1173 size_t cur_used_bytes = _g1->used(); |
1190 assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); | 1174 assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); |
1191 bool last_pause_included_initial_mark = false; | 1175 bool last_pause_included_initial_mark = false; |
1254 (double)surviving_bytes/ | 1238 (double)surviving_bytes/ |
1255 (double)_collection_set_bytes_used_before; | 1239 (double)_collection_set_bytes_used_before; |
1256 | 1240 |
1257 _n_pauses++; | 1241 _n_pauses++; |
1258 | 1242 |
1243 double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms); | |
1244 double mark_stack_scan_time = avg_value(_par_last_mark_stack_scan_times_ms); | |
1245 double update_rs_time = avg_value(_par_last_update_rs_times_ms); | |
1246 double update_rs_processed_buffers = | |
1247 sum_of_values(_par_last_update_rs_processed_buffers); | |
1248 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms); | |
1249 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms); | |
1250 double termination_time = avg_value(_par_last_termination_times_ms); | |
1251 | |
1252 double parallel_known_time = update_rs_time + | |
1253 ext_root_scan_time + | |
1254 mark_stack_scan_time + | |
1255 scan_rs_time + | |
1256 obj_copy_time + | |
1257 termination_time; | |
1258 | |
1259 double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time; | |
1260 | |
1261 PauseSummary* summary = _summary; | |
1262 | |
1259 if (update_stats) { | 1263 if (update_stats) { |
1260 _recent_CH_strong_roots_times_ms->add(_cur_CH_strong_roots_dur_ms); | 1264 _recent_rs_scan_times_ms->add(scan_rs_time); |
1261 _recent_G1_strong_roots_times_ms->add(_cur_G1_strong_roots_dur_ms); | |
1262 _recent_evac_times_ms->add(evac_ms); | |
1263 _recent_pause_times_ms->add(elapsed_ms); | 1265 _recent_pause_times_ms->add(elapsed_ms); |
1264 | |
1265 _recent_rs_sizes->add(rs_size); | 1266 _recent_rs_sizes->add(rs_size); |
1267 | |
1268 MainBodySummary* body_summary = summary->main_body_summary(); | |
1269 guarantee(body_summary != NULL, "should not be null!"); | |
1270 | |
1271 if (_satb_drain_time_set) | |
1272 body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms); | |
1273 else | |
1274 body_summary->record_satb_drain_time_ms(0.0); | |
1275 | |
1276 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time); | |
1277 body_summary->record_mark_stack_scan_time_ms(mark_stack_scan_time); | |
1278 body_summary->record_update_rs_time_ms(update_rs_time); | |
1279 body_summary->record_scan_rs_time_ms(scan_rs_time); | |
1280 body_summary->record_obj_copy_time_ms(obj_copy_time); | |
1281 if (parallel) { | |
1282 body_summary->record_parallel_time_ms(_cur_collection_par_time_ms); | |
1283 body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms); | |
1284 body_summary->record_termination_time_ms(termination_time); | |
1285 body_summary->record_parallel_other_time_ms(parallel_other_time); | |
1286 } | |
1287 body_summary->record_mark_closure_time_ms(_mark_closure_time_ms); | |
1266 | 1288 |
1267 // We exempt parallel collection from this check because Alloc Buffer | 1289 // We exempt parallel collection from this check because Alloc Buffer |
1268 // fragmentation can produce negative collections. Same with evac | 1290 // fragmentation can produce negative collections. Same with evac |
1269 // failure. | 1291 // failure. |
1270 // Further, we're now always doing parallel collection. But I'm still | 1292 // Further, we're now always doing parallel collection. But I'm still |
1326 | 1348 |
1327 if (G1PolicyVerbose > 1) { | 1349 if (G1PolicyVerbose > 1) { |
1328 gclog_or_tty->print_cr(" Recording collection pause(%d)", _n_pauses); | 1350 gclog_or_tty->print_cr(" Recording collection pause(%d)", _n_pauses); |
1329 } | 1351 } |
1330 | 1352 |
1331 PauseSummary* summary = _summary; | |
1332 | |
1333 double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms); | |
1334 double mark_stack_scan_time = avg_value(_par_last_mark_stack_scan_times_ms); | |
1335 double update_rs_time = avg_value(_par_last_update_rs_times_ms); | |
1336 double update_rs_processed_buffers = | |
1337 sum_of_values(_par_last_update_rs_processed_buffers); | |
1338 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms); | |
1339 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms); | |
1340 double termination_time = avg_value(_par_last_termination_times_ms); | |
1341 | |
1342 double parallel_other_time = _cur_collection_par_time_ms - | |
1343 (update_rs_time + ext_root_scan_time + mark_stack_scan_time + | |
1344 scan_rs_time + obj_copy_time + termination_time); | |
1345 if (update_stats) { | |
1346 MainBodySummary* body_summary = summary->main_body_summary(); | |
1347 guarantee(body_summary != NULL, "should not be null!"); | |
1348 | |
1349 if (_satb_drain_time_set) | |
1350 body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms); | |
1351 else | |
1352 body_summary->record_satb_drain_time_ms(0.0); | |
1353 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time); | |
1354 body_summary->record_mark_stack_scan_time_ms(mark_stack_scan_time); | |
1355 body_summary->record_update_rs_time_ms(update_rs_time); | |
1356 body_summary->record_scan_rs_time_ms(scan_rs_time); | |
1357 body_summary->record_obj_copy_time_ms(obj_copy_time); | |
1358 if (parallel) { | |
1359 body_summary->record_parallel_time_ms(_cur_collection_par_time_ms); | |
1360 body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms); | |
1361 body_summary->record_termination_time_ms(termination_time); | |
1362 body_summary->record_parallel_other_time_ms(parallel_other_time); | |
1363 } | |
1364 body_summary->record_mark_closure_time_ms(_mark_closure_time_ms); | |
1365 } | |
1366 | |
1367 if (G1PolicyVerbose > 1) { | 1353 if (G1PolicyVerbose > 1) { |
1368 gclog_or_tty->print_cr(" ET: %10.6f ms (avg: %10.6f ms)\n" | 1354 gclog_or_tty->print_cr(" ET: %10.6f ms (avg: %10.6f ms)\n" |
1369 " CH Strong: %10.6f ms (avg: %10.6f ms)\n" | |
1370 " G1 Strong: %10.6f ms (avg: %10.6f ms)\n" | |
1371 " Evac: %10.6f ms (avg: %10.6f ms)\n" | |
1372 " ET-RS: %10.6f ms (avg: %10.6f ms)\n" | 1355 " ET-RS: %10.6f ms (avg: %10.6f ms)\n" |
1373 " |RS|: " SIZE_FORMAT, | 1356 " |RS|: " SIZE_FORMAT, |
1374 elapsed_ms, recent_avg_time_for_pauses_ms(), | 1357 elapsed_ms, recent_avg_time_for_pauses_ms(), |
1375 _cur_CH_strong_roots_dur_ms, recent_avg_time_for_CH_strong_ms(), | 1358 scan_rs_time, recent_avg_time_for_rs_scan_ms(), |
1376 _cur_G1_strong_roots_dur_ms, recent_avg_time_for_G1_strong_ms(), | |
1377 evac_ms, recent_avg_time_for_evac_ms(), | |
1378 scan_rs_time, | |
1379 recent_avg_time_for_pauses_ms() - | |
1380 recent_avg_time_for_G1_strong_ms(), | |
1381 rs_size); | 1359 rs_size); |
1382 | 1360 |
1383 gclog_or_tty->print_cr(" Used at start: " SIZE_FORMAT"K" | 1361 gclog_or_tty->print_cr(" Used at start: " SIZE_FORMAT"K" |
1384 " At end " SIZE_FORMAT "K\n" | 1362 " At end " SIZE_FORMAT "K\n" |
1385 " garbage : " SIZE_FORMAT "K" | 1363 " garbage : " SIZE_FORMAT "K" |
1436 for (int i = 0; i < _parallel_gc_threads; i++) { | 1414 for (int i = 0; i < _parallel_gc_threads; i++) { |
1437 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - _par_last_gc_worker_start_times_ms[i]; | 1415 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - _par_last_gc_worker_start_times_ms[i]; |
1438 } | 1416 } |
1439 print_par_stats(2, "GC Worker Times", _par_last_gc_worker_times_ms); | 1417 print_par_stats(2, "GC Worker Times", _par_last_gc_worker_times_ms); |
1440 | 1418 |
1441 print_stats(2, "Other", parallel_other_time); | 1419 print_stats(2, "Parallel Other", parallel_other_time); |
1442 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); | 1420 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); |
1443 } else { | 1421 } else { |
1444 print_stats(1, "Update RS", update_rs_time); | 1422 print_stats(1, "Update RS", update_rs_time); |
1445 print_stats(2, "Processed Buffers", | 1423 print_stats(2, "Processed Buffers", |
1446 (int)update_rs_processed_buffers); | 1424 (int)update_rs_processed_buffers); |
1965 _recent_prev_end_times_for_all_gcs_sec->add(end_time_sec); | 1943 _recent_prev_end_times_for_all_gcs_sec->add(end_time_sec); |
1966 _prev_collection_pause_end_ms = end_time_sec * 1000.0; | 1944 _prev_collection_pause_end_ms = end_time_sec * 1000.0; |
1967 } | 1945 } |
1968 | 1946 |
1969 double G1CollectorPolicy::recent_avg_time_for_pauses_ms() { | 1947 double G1CollectorPolicy::recent_avg_time_for_pauses_ms() { |
1970 if (_recent_pause_times_ms->num() == 0) return (double) MaxGCPauseMillis; | 1948 if (_recent_pause_times_ms->num() == 0) { |
1971 else return _recent_pause_times_ms->avg(); | 1949 return (double) MaxGCPauseMillis; |
1972 } | 1950 } |
1973 | 1951 return _recent_pause_times_ms->avg(); |
1974 double G1CollectorPolicy::recent_avg_time_for_CH_strong_ms() { | 1952 } |
1975 if (_recent_CH_strong_roots_times_ms->num() == 0) | 1953 |
1954 double G1CollectorPolicy::recent_avg_time_for_rs_scan_ms() { | |
1955 if (_recent_rs_scan_times_ms->num() == 0) { | |
1976 return (double)MaxGCPauseMillis/3.0; | 1956 return (double)MaxGCPauseMillis/3.0; |
1977 else return _recent_CH_strong_roots_times_ms->avg(); | 1957 } |
1978 } | 1958 return _recent_rs_scan_times_ms->avg(); |
1979 | |
1980 double G1CollectorPolicy::recent_avg_time_for_G1_strong_ms() { | |
1981 if (_recent_G1_strong_roots_times_ms->num() == 0) | |
1982 return (double)MaxGCPauseMillis/3.0; | |
1983 else return _recent_G1_strong_roots_times_ms->avg(); | |
1984 } | |
1985 | |
1986 double G1CollectorPolicy::recent_avg_time_for_evac_ms() { | |
1987 if (_recent_evac_times_ms->num() == 0) return (double)MaxGCPauseMillis/3.0; | |
1988 else return _recent_evac_times_ms->avg(); | |
1989 } | 1959 } |
1990 | 1960 |
1991 int G1CollectorPolicy::number_of_recent_gcs() { | 1961 int G1CollectorPolicy::number_of_recent_gcs() { |
1992 assert(_recent_CH_strong_roots_times_ms->num() == | 1962 assert(_recent_rs_scan_times_ms->num() == |
1993 _recent_G1_strong_roots_times_ms->num(), "Sequence out of sync"); | |
1994 assert(_recent_G1_strong_roots_times_ms->num() == | |
1995 _recent_evac_times_ms->num(), "Sequence out of sync"); | |
1996 assert(_recent_evac_times_ms->num() == | |
1997 _recent_pause_times_ms->num(), "Sequence out of sync"); | 1963 _recent_pause_times_ms->num(), "Sequence out of sync"); |
1998 assert(_recent_pause_times_ms->num() == | 1964 assert(_recent_pause_times_ms->num() == |
1999 _recent_CS_bytes_used_before->num(), "Sequence out of sync"); | 1965 _recent_CS_bytes_used_before->num(), "Sequence out of sync"); |
2000 assert(_recent_CS_bytes_used_before->num() == | 1966 assert(_recent_CS_bytes_used_before->num() == |
2001 _recent_CS_bytes_surviving->num(), "Sequence out of sync"); | 1967 _recent_CS_bytes_surviving->num(), "Sequence out of sync"); |
1968 | |
2002 return _recent_pause_times_ms->num(); | 1969 return _recent_pause_times_ms->num(); |
2003 } | 1970 } |
2004 | 1971 |
2005 double G1CollectorPolicy::recent_avg_survival_fraction() { | 1972 double G1CollectorPolicy::recent_avg_survival_fraction() { |
2006 return recent_avg_survival_fraction_work(_recent_CS_bytes_surviving, | 1973 return recent_avg_survival_fraction_work(_recent_CS_bytes_surviving, |