Mercurial > hg > graal-jvmci-8
comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 4023:c6a6e936dc68
7096030: G1: PrintGCDetails enhancements
7102445: G1: Unnecessary Resource allocations during RSet scanning
Summary: Add a new per-worker thread line in the PrintGCDetails output. GC Worker Other is the difference between the elapsed time for the parallel phase of the evacuation pause and the sum of the times of the sub-phases (external root scanning, mark stack scanning, RSet updating, RSet scanning, object copying, and termination) for that worker. During RSet scanning, stack allocate DirtyCardToOopClosure objects; allocating these in a resource area was causing abnormally high GC Worker Other times while the worker thread freed ResourceArea chunks.
Reviewed-by: tonyp, jwilhelm, brutisso
author | johnc |
---|---|
date | Sun, 23 Oct 2011 23:06:06 -0700 |
parents | 074f0252cc13 |
children | dbfcbecbb2dc |
comparison
equal
deleted
inserted
replaced
4022:db89aa49298f | 4023:c6a6e936dc68 |
---|---|
318 | 318 |
319 _par_last_termination_times_ms = new double[_parallel_gc_threads]; | 319 _par_last_termination_times_ms = new double[_parallel_gc_threads]; |
320 _par_last_termination_attempts = new double[_parallel_gc_threads]; | 320 _par_last_termination_attempts = new double[_parallel_gc_threads]; |
321 _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads]; | 321 _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads]; |
322 _par_last_gc_worker_times_ms = new double[_parallel_gc_threads]; | 322 _par_last_gc_worker_times_ms = new double[_parallel_gc_threads]; |
323 _par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads]; | |
323 | 324 |
324 // start conservatively | 325 // start conservatively |
325 _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis; | 326 _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis; |
326 | 327 |
327 // <NEW PREDICTION> | 328 // <NEW PREDICTION> |
974 _par_last_obj_copy_times_ms[i] = -1234.0; | 975 _par_last_obj_copy_times_ms[i] = -1234.0; |
975 _par_last_termination_times_ms[i] = -1234.0; | 976 _par_last_termination_times_ms[i] = -1234.0; |
976 _par_last_termination_attempts[i] = -1234.0; | 977 _par_last_termination_attempts[i] = -1234.0; |
977 _par_last_gc_worker_end_times_ms[i] = -1234.0; | 978 _par_last_gc_worker_end_times_ms[i] = -1234.0; |
978 _par_last_gc_worker_times_ms[i] = -1234.0; | 979 _par_last_gc_worker_times_ms[i] = -1234.0; |
980 _par_last_gc_worker_other_times_ms[i] = -1234.0; | |
979 } | 981 } |
980 #endif | 982 #endif |
981 | 983 |
982 for (int i = 0; i < _aux_num; ++i) { | 984 for (int i = 0; i < _aux_num; ++i) { |
983 _cur_aux_times_ms[i] = 0.0; | 985 _cur_aux_times_ms[i] = 0.0; |
984 _cur_aux_times_set[i] = false; | 986 _cur_aux_times_set[i] = false; |
985 } | 987 } |
986 | 988 |
987 _satb_drain_time_set = false; | 989 // These are initialized to zero here and they are set during |
988 _last_satb_drain_processed_buffers = -1; | 990 // the evacuation pause if marking is in progress. |
991 _cur_satb_drain_time_ms = 0.0; | |
992 _last_satb_drain_processed_buffers = 0; | |
989 | 993 |
990 _last_young_gc_full = false; | 994 _last_young_gc_full = false; |
991 | 995 |
992 // do that for any other surv rate groups | 996 // do that for any other surv rate groups |
993 _short_lived_surv_rate_group->stop_adding_regions(); | 997 _short_lived_surv_rate_group->stop_adding_regions(); |
1095 double avg = total / (double) ParallelGCThreads; | 1099 double avg = total / (double) ParallelGCThreads; |
1096 buf.append_and_print_cr(" Sum: %d, Avg: %d, Min: %d, Max: %d, Diff: %d]", | 1100 buf.append_and_print_cr(" Sum: %d, Avg: %d, Min: %d, Max: %d, Diff: %d]", |
1097 (int)total, (int)avg, (int)min, (int)max, (int)max - (int)min); | 1101 (int)total, (int)avg, (int)min, (int)max, (int)max - (int)min); |
1098 } | 1102 } |
1099 | 1103 |
1100 void G1CollectorPolicy::print_stats (int level, | 1104 void G1CollectorPolicy::print_stats(int level, |
1101 const char* str, | 1105 const char* str, |
1102 double value) { | 1106 double value) { |
1103 LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value); | 1107 LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value); |
1104 } | 1108 } |
1105 | 1109 |
1106 void G1CollectorPolicy::print_stats (int level, | 1110 void G1CollectorPolicy::print_stats(int level, |
1107 const char* str, | 1111 const char* str, |
1108 int value) { | 1112 int value) { |
1109 LineBuffer(level).append_and_print_cr("[%s: %d]", str, value); | 1113 LineBuffer(level).append_and_print_cr("[%s: %d]", str, value); |
1110 } | 1114 } |
1111 | 1115 |
1112 double G1CollectorPolicy::avg_value (double* data) { | 1116 double G1CollectorPolicy::avg_value(double* data) { |
1113 if (G1CollectedHeap::use_parallel_gc_threads()) { | 1117 if (G1CollectedHeap::use_parallel_gc_threads()) { |
1114 double ret = 0.0; | 1118 double ret = 0.0; |
1115 for (uint i = 0; i < ParallelGCThreads; ++i) | 1119 for (uint i = 0; i < ParallelGCThreads; ++i) { |
1116 ret += data[i]; | 1120 ret += data[i]; |
1121 } | |
1117 return ret / (double) ParallelGCThreads; | 1122 return ret / (double) ParallelGCThreads; |
1118 } else { | 1123 } else { |
1119 return data[0]; | 1124 return data[0]; |
1120 } | 1125 } |
1121 } | 1126 } |
1122 | 1127 |
1123 double G1CollectorPolicy::max_value (double* data) { | 1128 double G1CollectorPolicy::max_value(double* data) { |
1124 if (G1CollectedHeap::use_parallel_gc_threads()) { | 1129 if (G1CollectedHeap::use_parallel_gc_threads()) { |
1125 double ret = data[0]; | 1130 double ret = data[0]; |
1126 for (uint i = 1; i < ParallelGCThreads; ++i) | 1131 for (uint i = 1; i < ParallelGCThreads; ++i) { |
1127 if (data[i] > ret) | 1132 if (data[i] > ret) { |
1128 ret = data[i]; | 1133 ret = data[i]; |
1134 } | |
1135 } | |
1129 return ret; | 1136 return ret; |
1130 } else { | 1137 } else { |
1131 return data[0]; | 1138 return data[0]; |
1132 } | 1139 } |
1133 } | 1140 } |
1134 | 1141 |
1135 double G1CollectorPolicy::sum_of_values (double* data) { | 1142 double G1CollectorPolicy::sum_of_values(double* data) { |
1136 if (G1CollectedHeap::use_parallel_gc_threads()) { | 1143 if (G1CollectedHeap::use_parallel_gc_threads()) { |
1137 double sum = 0.0; | 1144 double sum = 0.0; |
1138 for (uint i = 0; i < ParallelGCThreads; i++) | 1145 for (uint i = 0; i < ParallelGCThreads; i++) { |
1139 sum += data[i]; | 1146 sum += data[i]; |
1147 } | |
1140 return sum; | 1148 return sum; |
1141 } else { | 1149 } else { |
1142 return data[0]; | 1150 return data[0]; |
1143 } | 1151 } |
1144 } | 1152 } |
1145 | 1153 |
1146 double G1CollectorPolicy::max_sum (double* data1, | 1154 double G1CollectorPolicy::max_sum(double* data1, double* data2) { |
1147 double* data2) { | |
1148 double ret = data1[0] + data2[0]; | 1155 double ret = data1[0] + data2[0]; |
1149 | 1156 |
1150 if (G1CollectedHeap::use_parallel_gc_threads()) { | 1157 if (G1CollectedHeap::use_parallel_gc_threads()) { |
1151 for (uint i = 1; i < ParallelGCThreads; ++i) { | 1158 for (uint i = 1; i < ParallelGCThreads; ++i) { |
1152 double data = data1[i] + data2[i]; | 1159 double data = data1[i] + data2[i]; |
1153 if (data > ret) | 1160 if (data > ret) { |
1154 ret = data; | 1161 ret = data; |
1162 } | |
1155 } | 1163 } |
1156 } | 1164 } |
1157 return ret; | 1165 return ret; |
1158 } | 1166 } |
1159 | 1167 |
1249 (double)surviving_bytes/ | 1257 (double)surviving_bytes/ |
1250 (double)_collection_set_bytes_used_before; | 1258 (double)_collection_set_bytes_used_before; |
1251 | 1259 |
1252 _n_pauses++; | 1260 _n_pauses++; |
1253 | 1261 |
1262 // These values are used to update the summary information that is | |
1263 // displayed when TraceGen0Time is enabled, and are output as part | |
1264 // of the PrintGCDetails output, in the non-parallel case. | |
1265 | |
1254 double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms); | 1266 double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms); |
1255 double mark_stack_scan_time = avg_value(_par_last_mark_stack_scan_times_ms); | 1267 double mark_stack_scan_time = avg_value(_par_last_mark_stack_scan_times_ms); |
1256 double update_rs_time = avg_value(_par_last_update_rs_times_ms); | 1268 double update_rs_time = avg_value(_par_last_update_rs_times_ms); |
1257 double update_rs_processed_buffers = | 1269 double update_rs_processed_buffers = |
1258 sum_of_values(_par_last_update_rs_processed_buffers); | 1270 sum_of_values(_par_last_update_rs_processed_buffers); |
1259 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms); | 1271 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms); |
1260 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms); | 1272 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms); |
1261 double termination_time = avg_value(_par_last_termination_times_ms); | 1273 double termination_time = avg_value(_par_last_termination_times_ms); |
1262 | 1274 |
1263 double parallel_known_time = update_rs_time + | 1275 double known_time = ext_root_scan_time + |
1264 ext_root_scan_time + | 1276 mark_stack_scan_time + |
1265 mark_stack_scan_time + | 1277 update_rs_time + |
1266 scan_rs_time + | 1278 scan_rs_time + |
1267 obj_copy_time + | 1279 obj_copy_time; |
1268 termination_time; | 1280 |
1269 | 1281 double other_time_ms = elapsed_ms; |
1270 double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time; | 1282 |
1271 | 1283 // Subtract the SATB drain time. It's initialized to zero at the |
1272 PauseSummary* summary = _summary; | 1284 // start of the pause and is updated during the pause if marking |
1285 // is in progress. | |
1286 other_time_ms -= _cur_satb_drain_time_ms; | |
1287 | |
1288 if (parallel) { | |
1289 other_time_ms -= _cur_collection_par_time_ms; | |
1290 } else { | |
1291 other_time_ms -= known_time; | |
1292 } | |
1293 | |
1294 // Subtract the time taken to clean the card table from the | |
1295 // current value of "other time" | |
1296 other_time_ms -= _cur_clear_ct_time_ms; | |
1297 | |
1298 // TraceGen0Time and TraceGen1Time summary info updating. | |
1299 _all_pause_times_ms->add(elapsed_ms); | |
1273 | 1300 |
1274 if (update_stats) { | 1301 if (update_stats) { |
1275 _recent_rs_scan_times_ms->add(scan_rs_time); | 1302 _recent_rs_scan_times_ms->add(scan_rs_time); |
1276 _recent_pause_times_ms->add(elapsed_ms); | 1303 _recent_pause_times_ms->add(elapsed_ms); |
1277 _recent_rs_sizes->add(rs_size); | 1304 _recent_rs_sizes->add(rs_size); |
1278 | 1305 |
1279 MainBodySummary* body_summary = summary->main_body_summary(); | 1306 _summary->record_total_time_ms(elapsed_ms); |
1280 guarantee(body_summary != NULL, "should not be null!"); | 1307 _summary->record_other_time_ms(other_time_ms); |
1281 | 1308 |
1282 if (_satb_drain_time_set) | 1309 MainBodySummary* body_summary = _summary->main_body_summary(); |
1283 body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms); | 1310 assert(body_summary != NULL, "should not be null!"); |
1284 else | 1311 |
1285 body_summary->record_satb_drain_time_ms(0.0); | 1312 // This will be non-zero iff marking is currently in progress (i.e. |
1313 // _g1->mark_in_progress() == true) and the currrent pause was not | |
1314 // an initial mark pause. Since the body_summary items are NumberSeqs, | |
1315 // however, they have to be consistent and updated in lock-step with | |
1316 // each other. Therefore we unconditionally record the SATB drain | |
1317 // time - even if it's zero. | |
1318 body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms); | |
1286 | 1319 |
1287 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time); | 1320 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time); |
1288 body_summary->record_mark_stack_scan_time_ms(mark_stack_scan_time); | 1321 body_summary->record_mark_stack_scan_time_ms(mark_stack_scan_time); |
1289 body_summary->record_update_rs_time_ms(update_rs_time); | 1322 body_summary->record_update_rs_time_ms(update_rs_time); |
1290 body_summary->record_scan_rs_time_ms(scan_rs_time); | 1323 body_summary->record_scan_rs_time_ms(scan_rs_time); |
1291 body_summary->record_obj_copy_time_ms(obj_copy_time); | 1324 body_summary->record_obj_copy_time_ms(obj_copy_time); |
1325 | |
1292 if (parallel) { | 1326 if (parallel) { |
1293 body_summary->record_parallel_time_ms(_cur_collection_par_time_ms); | 1327 body_summary->record_parallel_time_ms(_cur_collection_par_time_ms); |
1294 body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms); | |
1295 body_summary->record_termination_time_ms(termination_time); | 1328 body_summary->record_termination_time_ms(termination_time); |
1329 | |
1330 double parallel_known_time = known_time + termination_time; | |
1331 double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time; | |
1296 body_summary->record_parallel_other_time_ms(parallel_other_time); | 1332 body_summary->record_parallel_other_time_ms(parallel_other_time); |
1297 } | 1333 } |
1334 | |
1298 body_summary->record_mark_closure_time_ms(_mark_closure_time_ms); | 1335 body_summary->record_mark_closure_time_ms(_mark_closure_time_ms); |
1336 body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms); | |
1299 | 1337 |
1300 // We exempt parallel collection from this check because Alloc Buffer | 1338 // We exempt parallel collection from this check because Alloc Buffer |
1301 // fragmentation can produce negative collections. Same with evac | 1339 // fragmentation can produce negative collections. Same with evac |
1302 // failure. | 1340 // failure. |
1303 // Further, we're now always doing parallel collection. But I'm still | 1341 // Further, we're now always doing parallel collection. But I'm still |
1305 // (DLD, 10/05. | 1343 // (DLD, 10/05. |
1306 assert((true || parallel) | 1344 assert((true || parallel) |
1307 || _g1->evacuation_failed() | 1345 || _g1->evacuation_failed() |
1308 || surviving_bytes <= _collection_set_bytes_used_before, | 1346 || surviving_bytes <= _collection_set_bytes_used_before, |
1309 "Or else negative collection!"); | 1347 "Or else negative collection!"); |
1348 | |
1310 _recent_CS_bytes_used_before->add(_collection_set_bytes_used_before); | 1349 _recent_CS_bytes_used_before->add(_collection_set_bytes_used_before); |
1311 _recent_CS_bytes_surviving->add(surviving_bytes); | 1350 _recent_CS_bytes_surviving->add(surviving_bytes); |
1312 | 1351 |
1313 // this is where we update the allocation rate of the application | 1352 // this is where we update the allocation rate of the application |
1314 double app_time_ms = | 1353 double app_time_ms = |
1355 _recent_avg_pause_time_ratio = 1.0; | 1394 _recent_avg_pause_time_ratio = 1.0; |
1356 } | 1395 } |
1357 } | 1396 } |
1358 } | 1397 } |
1359 | 1398 |
1399 for (int i = 0; i < _aux_num; ++i) { | |
1400 if (_cur_aux_times_set[i]) { | |
1401 _all_aux_times_ms[i].add(_cur_aux_times_ms[i]); | |
1402 } | |
1403 } | |
1404 | |
1405 | |
1360 if (G1PolicyVerbose > 1) { | 1406 if (G1PolicyVerbose > 1) { |
1361 gclog_or_tty->print_cr(" Recording collection pause(%d)", _n_pauses); | 1407 gclog_or_tty->print_cr(" Recording collection pause(%d)", _n_pauses); |
1362 } | 1408 } |
1363 | 1409 |
1364 if (G1PolicyVerbose > 1) { | 1410 if (G1PolicyVerbose > 1) { |
1381 recent_avg_survival_fraction()*100.0); | 1427 recent_avg_survival_fraction()*100.0); |
1382 gclog_or_tty->print_cr(" Recent %% gc pause time: %6.2f", | 1428 gclog_or_tty->print_cr(" Recent %% gc pause time: %6.2f", |
1383 recent_avg_pause_time_ratio() * 100.0); | 1429 recent_avg_pause_time_ratio() * 100.0); |
1384 } | 1430 } |
1385 | 1431 |
1386 double other_time_ms = elapsed_ms; | 1432 // PrintGCDetails output |
1387 | |
1388 if (_satb_drain_time_set) { | |
1389 other_time_ms -= _cur_satb_drain_time_ms; | |
1390 } | |
1391 | |
1392 if (parallel) { | |
1393 other_time_ms -= _cur_collection_par_time_ms + _cur_clear_ct_time_ms; | |
1394 } else { | |
1395 other_time_ms -= | |
1396 update_rs_time + | |
1397 ext_root_scan_time + mark_stack_scan_time + | |
1398 scan_rs_time + obj_copy_time; | |
1399 } | |
1400 | |
1401 if (PrintGCDetails) { | 1433 if (PrintGCDetails) { |
1434 bool print_marking_info = | |
1435 _g1->mark_in_progress() && !last_pause_included_initial_mark; | |
1436 | |
1402 gclog_or_tty->print_cr("%s, %1.8lf secs]", | 1437 gclog_or_tty->print_cr("%s, %1.8lf secs]", |
1403 (last_pause_included_initial_mark) ? " (initial-mark)" : "", | 1438 (last_pause_included_initial_mark) ? " (initial-mark)" : "", |
1404 elapsed_ms / 1000.0); | 1439 elapsed_ms / 1000.0); |
1405 | 1440 |
1406 if (_satb_drain_time_set) { | 1441 if (print_marking_info) { |
1407 print_stats(1, "SATB Drain Time", _cur_satb_drain_time_ms); | 1442 print_stats(1, "SATB Drain Time", _cur_satb_drain_time_ms); |
1408 } | |
1409 if (_last_satb_drain_processed_buffers >= 0) { | |
1410 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers); | 1443 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers); |
1411 } | 1444 } |
1445 | |
1412 if (parallel) { | 1446 if (parallel) { |
1413 print_stats(1, "Parallel Time", _cur_collection_par_time_ms); | 1447 print_stats(1, "Parallel Time", _cur_collection_par_time_ms); |
1414 print_par_stats(2, "GC Worker Start Time", _par_last_gc_worker_start_times_ms); | 1448 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms); |
1449 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); | |
1450 if (print_marking_info) { | |
1451 print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms); | |
1452 } | |
1415 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); | 1453 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); |
1416 print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers); | 1454 print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers); |
1417 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); | |
1418 print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms); | |
1419 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); | 1455 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); |
1420 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); | 1456 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); |
1421 print_par_stats(2, "Termination", _par_last_termination_times_ms); | 1457 print_par_stats(2, "Termination", _par_last_termination_times_ms); |
1422 print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts); | 1458 print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts); |
1423 print_par_stats(2, "GC Worker End Time", _par_last_gc_worker_end_times_ms); | 1459 print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms); |
1424 | 1460 |
1425 for (int i = 0; i < _parallel_gc_threads; i++) { | 1461 for (int i = 0; i < _parallel_gc_threads; i++) { |
1426 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - _par_last_gc_worker_start_times_ms[i]; | 1462 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - _par_last_gc_worker_start_times_ms[i]; |
1463 | |
1464 double worker_known_time = _par_last_ext_root_scan_times_ms[i] + | |
1465 _par_last_mark_stack_scan_times_ms[i] + | |
1466 _par_last_update_rs_times_ms[i] + | |
1467 _par_last_scan_rs_times_ms[i] + | |
1468 _par_last_obj_copy_times_ms[i] + | |
1469 _par_last_termination_times_ms[i]; | |
1470 | |
1471 _par_last_gc_worker_other_times_ms[i] = _cur_collection_par_time_ms - worker_known_time; | |
1427 } | 1472 } |
1428 print_par_stats(2, "GC Worker Times", _par_last_gc_worker_times_ms); | 1473 print_par_stats(2, "GC Worker", _par_last_gc_worker_times_ms); |
1429 | 1474 print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms); |
1430 print_stats(2, "Parallel Other", parallel_other_time); | |
1431 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); | |
1432 } else { | 1475 } else { |
1476 print_stats(1, "Ext Root Scanning", ext_root_scan_time); | |
1477 if (print_marking_info) { | |
1478 print_stats(1, "Mark Stack Scanning", mark_stack_scan_time); | |
1479 } | |
1433 print_stats(1, "Update RS", update_rs_time); | 1480 print_stats(1, "Update RS", update_rs_time); |
1434 print_stats(2, "Processed Buffers", | 1481 print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers); |
1435 (int)update_rs_processed_buffers); | |
1436 print_stats(1, "Ext Root Scanning", ext_root_scan_time); | |
1437 print_stats(1, "Mark Stack Scanning", mark_stack_scan_time); | |
1438 print_stats(1, "Scan RS", scan_rs_time); | 1482 print_stats(1, "Scan RS", scan_rs_time); |
1439 print_stats(1, "Object Copying", obj_copy_time); | 1483 print_stats(1, "Object Copying", obj_copy_time); |
1440 } | 1484 } |
1485 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); | |
1441 #ifndef PRODUCT | 1486 #ifndef PRODUCT |
1442 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); | 1487 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); |
1443 print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms); | 1488 print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms); |
1444 print_stats(1, "Min Clear CC", _min_clear_cc_time_ms); | 1489 print_stats(1, "Min Clear CC", _min_clear_cc_time_ms); |
1445 print_stats(1, "Max Clear CC", _max_clear_cc_time_ms); | 1490 print_stats(1, "Max Clear CC", _max_clear_cc_time_ms); |
1458 sprintf(buffer, "Aux%d", i); | 1503 sprintf(buffer, "Aux%d", i); |
1459 print_stats(1, buffer, _cur_aux_times_ms[i]); | 1504 print_stats(1, buffer, _cur_aux_times_ms[i]); |
1460 } | 1505 } |
1461 } | 1506 } |
1462 } | 1507 } |
1463 | |
1464 _all_pause_times_ms->add(elapsed_ms); | |
1465 if (update_stats) { | |
1466 summary->record_total_time_ms(elapsed_ms); | |
1467 summary->record_other_time_ms(other_time_ms); | |
1468 } | |
1469 for (int i = 0; i < _aux_num; ++i) | |
1470 if (_cur_aux_times_set[i]) { | |
1471 _all_aux_times_ms[i].add(_cur_aux_times_ms[i]); | |
1472 } | |
1473 | 1508 |
1474 // Update the efficiency-since-mark vars. | 1509 // Update the efficiency-since-mark vars. |
1475 double proc_ms = elapsed_ms * (double) _parallel_gc_threads; | 1510 double proc_ms = elapsed_ms * (double) _parallel_gc_threads; |
1476 if (elapsed_ms < MIN_TIMER_GRANULARITY) { | 1511 if (elapsed_ms < MIN_TIMER_GRANULARITY) { |
1477 // This usually happens due to the timer not having the required | 1512 // This usually happens due to the timer not having the required |
2136 void G1CollectorPolicy::count_CS_bytes_used() { | 2171 void G1CollectorPolicy::count_CS_bytes_used() { |
2137 CountCSClosure cs_closure(this); | 2172 CountCSClosure cs_closure(this); |
2138 _g1->collection_set_iterate(&cs_closure); | 2173 _g1->collection_set_iterate(&cs_closure); |
2139 } | 2174 } |
2140 | 2175 |
2141 void G1CollectorPolicy::print_summary (int level, | 2176 void G1CollectorPolicy::print_summary(int level, |
2142 const char* str, | 2177 const char* str, |
2143 NumberSeq* seq) const { | 2178 NumberSeq* seq) const { |
2144 double sum = seq->sum(); | 2179 double sum = seq->sum(); |
2145 LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", | 2180 LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", |
2146 str, sum / 1000.0, seq->avg()); | 2181 str, sum / 1000.0, seq->avg()); |
2147 } | 2182 } |
2148 | 2183 |
2149 void G1CollectorPolicy::print_summary_sd (int level, | 2184 void G1CollectorPolicy::print_summary_sd(int level, |
2150 const char* str, | 2185 const char* str, |
2151 NumberSeq* seq) const { | 2186 NumberSeq* seq) const { |
2152 print_summary(level, str, seq); | 2187 print_summary(level, str, seq); |
2153 LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", | 2188 LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", |
2154 seq->num(), seq->sd(), seq->maximum()); | 2189 seq->num(), seq->sd(), seq->maximum()); |
2155 } | 2190 } |
2156 | 2191 |
2209 print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq()); | 2244 print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq()); |
2210 if (body_summary != NULL) { | 2245 if (body_summary != NULL) { |
2211 print_summary(1, "SATB Drain", body_summary->get_satb_drain_seq()); | 2246 print_summary(1, "SATB Drain", body_summary->get_satb_drain_seq()); |
2212 if (parallel) { | 2247 if (parallel) { |
2213 print_summary(1, "Parallel Time", body_summary->get_parallel_seq()); | 2248 print_summary(1, "Parallel Time", body_summary->get_parallel_seq()); |
2249 print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq()); | |
2250 print_summary(2, "Mark Stack Scanning", body_summary->get_mark_stack_scan_seq()); | |
2214 print_summary(2, "Update RS", body_summary->get_update_rs_seq()); | 2251 print_summary(2, "Update RS", body_summary->get_update_rs_seq()); |
2215 print_summary(2, "Ext Root Scanning", | |
2216 body_summary->get_ext_root_scan_seq()); | |
2217 print_summary(2, "Mark Stack Scanning", | |
2218 body_summary->get_mark_stack_scan_seq()); | |
2219 print_summary(2, "Scan RS", body_summary->get_scan_rs_seq()); | 2252 print_summary(2, "Scan RS", body_summary->get_scan_rs_seq()); |
2220 print_summary(2, "Object Copy", body_summary->get_obj_copy_seq()); | 2253 print_summary(2, "Object Copy", body_summary->get_obj_copy_seq()); |
2221 print_summary(2, "Termination", body_summary->get_termination_seq()); | 2254 print_summary(2, "Termination", body_summary->get_termination_seq()); |
2222 print_summary(2, "Other", body_summary->get_parallel_other_seq()); | 2255 print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq()); |
2223 { | 2256 { |
2224 NumberSeq* other_parts[] = { | 2257 NumberSeq* other_parts[] = { |
2225 body_summary->get_update_rs_seq(), | |
2226 body_summary->get_ext_root_scan_seq(), | 2258 body_summary->get_ext_root_scan_seq(), |
2227 body_summary->get_mark_stack_scan_seq(), | 2259 body_summary->get_mark_stack_scan_seq(), |
2260 body_summary->get_update_rs_seq(), | |
2228 body_summary->get_scan_rs_seq(), | 2261 body_summary->get_scan_rs_seq(), |
2229 body_summary->get_obj_copy_seq(), | 2262 body_summary->get_obj_copy_seq(), |
2230 body_summary->get_termination_seq() | 2263 body_summary->get_termination_seq() |
2231 }; | 2264 }; |
2232 NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(), | 2265 NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(), |
2233 6, other_parts); | 2266 6, other_parts); |
2234 check_other_times(2, body_summary->get_parallel_other_seq(), | 2267 check_other_times(2, body_summary->get_parallel_other_seq(), |
2235 &calc_other_times_ms); | 2268 &calc_other_times_ms); |
2236 } | 2269 } |
2237 print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq()); | |
2238 print_summary(1, "Clear CT", body_summary->get_clear_ct_seq()); | |
2239 } else { | 2270 } else { |
2271 print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq()); | |
2272 print_summary(1, "Mark Stack Scanning", body_summary->get_mark_stack_scan_seq()); | |
2240 print_summary(1, "Update RS", body_summary->get_update_rs_seq()); | 2273 print_summary(1, "Update RS", body_summary->get_update_rs_seq()); |
2241 print_summary(1, "Ext Root Scanning", | |
2242 body_summary->get_ext_root_scan_seq()); | |
2243 print_summary(1, "Mark Stack Scanning", | |
2244 body_summary->get_mark_stack_scan_seq()); | |
2245 print_summary(1, "Scan RS", body_summary->get_scan_rs_seq()); | 2274 print_summary(1, "Scan RS", body_summary->get_scan_rs_seq()); |
2246 print_summary(1, "Object Copy", body_summary->get_obj_copy_seq()); | 2275 print_summary(1, "Object Copy", body_summary->get_obj_copy_seq()); |
2247 } | 2276 } |
2248 } | 2277 } |
2278 print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq()); | |
2279 print_summary(1, "Clear CT", body_summary->get_clear_ct_seq()); | |
2249 print_summary(1, "Other", summary->get_other_seq()); | 2280 print_summary(1, "Other", summary->get_other_seq()); |
2250 { | 2281 { |
2251 if (body_summary != NULL) { | 2282 if (body_summary != NULL) { |
2252 NumberSeq calc_other_times_ms; | 2283 NumberSeq calc_other_times_ms; |
2253 if (parallel) { | 2284 if (parallel) { |