comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 1611:215576b54709

6946048: G1: improvements to +PrintGCDetails output Summary: Small improvements to G1's PrintGCDetails output. It also includes minor formatting details. Reviewed-by: ysr, johnc
author tonyp
date Thu, 22 Apr 2010 15:20:16 -0400
parents 79107c3a6bd5
children 4e5661ba9d98
comparison
equal deleted inserted replaced
1610:79107c3a6bd5 1611:215576b54709
229 } 229 }
230 230
231 _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); 231 _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
232 _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; 232 _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
233 233
234 _par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads];
234 _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads]; 235 _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads];
235 _par_last_mark_stack_scan_times_ms = new double[_parallel_gc_threads]; 236 _par_last_mark_stack_scan_times_ms = new double[_parallel_gc_threads];
236 237
237 _par_last_update_rs_start_times_ms = new double[_parallel_gc_threads];
238 _par_last_update_rs_times_ms = new double[_parallel_gc_threads]; 238 _par_last_update_rs_times_ms = new double[_parallel_gc_threads];
239 _par_last_update_rs_processed_buffers = new double[_parallel_gc_threads]; 239 _par_last_update_rs_processed_buffers = new double[_parallel_gc_threads];
240 240
241 _par_last_scan_rs_start_times_ms = new double[_parallel_gc_threads];
242 _par_last_scan_rs_times_ms = new double[_parallel_gc_threads]; 241 _par_last_scan_rs_times_ms = new double[_parallel_gc_threads];
243 _par_last_scan_new_refs_times_ms = new double[_parallel_gc_threads]; 242 _par_last_scan_new_refs_times_ms = new double[_parallel_gc_threads];
244 243
245 _par_last_obj_copy_times_ms = new double[_parallel_gc_threads]; 244 _par_last_obj_copy_times_ms = new double[_parallel_gc_threads];
246 245
247 _par_last_termination_times_ms = new double[_parallel_gc_threads]; 246 _par_last_termination_times_ms = new double[_parallel_gc_threads];
247 _par_last_termination_attempts = new double[_parallel_gc_threads];
248 _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads];
248 249
249 // start conservatively 250 // start conservatively
250 _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis; 251 _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis;
251 252
252 // <NEW PREDICTION> 253 // <NEW PREDICTION>
834 #ifdef DEBUG 835 #ifdef DEBUG
835 // initialise these to something well known so that we can spot 836 // initialise these to something well known so that we can spot
836 // if they are not set properly 837 // if they are not set properly
837 838
838 for (int i = 0; i < _parallel_gc_threads; ++i) { 839 for (int i = 0; i < _parallel_gc_threads; ++i) {
839 _par_last_ext_root_scan_times_ms[i] = -666.0; 840 _par_last_gc_worker_start_times_ms[i] = -1234.0;
840 _par_last_mark_stack_scan_times_ms[i] = -666.0; 841 _par_last_ext_root_scan_times_ms[i] = -1234.0;
841 _par_last_update_rs_start_times_ms[i] = -666.0; 842 _par_last_mark_stack_scan_times_ms[i] = -1234.0;
842 _par_last_update_rs_times_ms[i] = -666.0; 843 _par_last_update_rs_times_ms[i] = -1234.0;
843 _par_last_update_rs_processed_buffers[i] = -666.0; 844 _par_last_update_rs_processed_buffers[i] = -1234.0;
844 _par_last_scan_rs_start_times_ms[i] = -666.0; 845 _par_last_scan_rs_times_ms[i] = -1234.0;
845 _par_last_scan_rs_times_ms[i] = -666.0; 846 _par_last_scan_new_refs_times_ms[i] = -1234.0;
846 _par_last_scan_new_refs_times_ms[i] = -666.0; 847 _par_last_obj_copy_times_ms[i] = -1234.0;
847 _par_last_obj_copy_times_ms[i] = -666.0; 848 _par_last_termination_times_ms[i] = -1234.0;
848 _par_last_termination_times_ms[i] = -666.0; 849 _par_last_termination_attempts[i] = -1234.0;
850 _par_last_gc_worker_end_times_ms[i] = -1234.0;
849 } 851 }
850 #endif 852 #endif
851 853
852 for (int i = 0; i < _aux_num; ++i) { 854 for (int i = 0; i < _aux_num; ++i) {
853 _cur_aux_times_ms[i] = 0.0; 855 _cur_aux_times_ms[i] = 0.0;
994 sum += sum_arr[j]; 996 sum += sum_arr[j];
995 } 997 }
996 return sum; 998 return sum;
997 } 999 }
998 1000
999 void G1CollectorPolicy::print_par_stats (int level, 1001 void G1CollectorPolicy::print_par_stats(int level,
1000 const char* str, 1002 const char* str,
1001 double* data, 1003 double* data,
1002 bool summary) { 1004 bool summary) {
1003 double min = data[0], max = data[0]; 1005 double min = data[0], max = data[0];
1004 double total = 0.0; 1006 double total = 0.0;
1005 int j; 1007 int j;
1006 for (j = 0; j < level; ++j) 1008 for (j = 0; j < level; ++j)
1025 avg, min, max); 1027 avg, min, max);
1026 } 1028 }
1027 gclog_or_tty->print_cr("]"); 1029 gclog_or_tty->print_cr("]");
1028 } 1030 }
1029 1031
1030 void G1CollectorPolicy::print_par_buffers (int level, 1032 void G1CollectorPolicy::print_par_sizes(int level,
1031 const char* str, 1033 const char* str,
1032 double* data, 1034 double* data,
1033 bool summary) { 1035 bool summary) {
1034 double min = data[0], max = data[0]; 1036 double min = data[0], max = data[0];
1035 double total = 0.0; 1037 double total = 0.0;
1036 int j; 1038 int j;
1037 for (j = 0; j < level; ++j) 1039 for (j = 0; j < level; ++j)
1038 gclog_or_tty->print(" "); 1040 gclog_or_tty->print(" ");
1373 if (_last_satb_drain_processed_buffers >= 0) { 1375 if (_last_satb_drain_processed_buffers >= 0) {
1374 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers); 1376 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers);
1375 } 1377 }
1376 if (parallel) { 1378 if (parallel) {
1377 print_stats(1, "Parallel Time", _cur_collection_par_time_ms); 1379 print_stats(1, "Parallel Time", _cur_collection_par_time_ms);
1378 print_par_stats(2, "Update RS (Start)", _par_last_update_rs_start_times_ms, false); 1380 print_par_stats(2, "GC Worker Start Time",
1381 _par_last_gc_worker_start_times_ms, false);
1379 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); 1382 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1380 print_par_buffers(3, "Processed Buffers", 1383 print_par_sizes(3, "Processed Buffers",
1381 _par_last_update_rs_processed_buffers, true); 1384 _par_last_update_rs_processed_buffers, true);
1382 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); 1385 print_par_stats(2, "Ext Root Scanning",
1383 print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms); 1386 _par_last_ext_root_scan_times_ms);
1387 print_par_stats(2, "Mark Stack Scanning",
1388 _par_last_mark_stack_scan_times_ms);
1384 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); 1389 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
1385 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); 1390 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
1386 print_par_stats(2, "Termination", _par_last_termination_times_ms); 1391 print_par_stats(2, "Termination", _par_last_termination_times_ms);
1392 print_par_sizes(3, "Termination Attempts",
1393 _par_last_termination_attempts, true);
1394 print_par_stats(2, "GC Worker End Time",
1395 _par_last_gc_worker_end_times_ms, false);
1387 print_stats(2, "Other", parallel_other_time); 1396 print_stats(2, "Other", parallel_other_time);
1388 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); 1397 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
1389 } else { 1398 } else {
1390 print_stats(1, "Update RS", update_rs_time); 1399 print_stats(1, "Update RS", update_rs_time);
1391 print_stats(2, "Processed Buffers", 1400 print_stats(2, "Processed Buffers",