Mercurial > hg > truffle

comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 3823:14a2fd14c0db

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
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,