comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 6059:3a22b77e755a

7161545: G1: Minor cleanups to the G1 logging Summary: Rename "to-space-overflow" to "to-space-exhausted", Introduce one decimal point in the size format, Add Sum to the aggregate and re-order the entries, Add number of GC workers to the log output Reviewed-by: johnc, jwilhelm
author brutisso
date Mon, 14 May 2012 17:32:17 +0200
parents 48fac5d60c3c
children 9d679effd28c
comparison
equal deleted inserted replaced
6054:56d1af561395 6059:3a22b77e755a
1008 return sum; 1008 return sum;
1009 } 1009 }
1010 1010
1011 void G1CollectorPolicy::print_par_stats(int level, 1011 void G1CollectorPolicy::print_par_stats(int level,
1012 const char* str, 1012 const char* str,
1013 double* data) { 1013 double* data,
1014 bool showDecimals) {
1014 double min = data[0], max = data[0]; 1015 double min = data[0], max = data[0];
1015 double total = 0.0; 1016 double total = 0.0;
1016 LineBuffer buf(level); 1017 LineBuffer buf(level);
1017 buf.append("[%s (ms):", str); 1018 buf.append("[%s (ms):", str);
1018 for (uint i = 0; i < no_of_gc_threads(); ++i) { 1019 for (uint i = 0; i < no_of_gc_threads(); ++i) {
1021 min = val; 1022 min = val;
1022 if (val > max) 1023 if (val > max)
1023 max = val; 1024 max = val;
1024 total += val; 1025 total += val;
1025 if (G1Log::finest()) { 1026 if (G1Log::finest()) {
1026 buf.append(" %.1lf", val); 1027 if (showDecimals) {
1028 buf.append(" %.1lf", val);
1029 } else {
1030 buf.append(" %d", (int)val);
1031 }
1027 } 1032 }
1028 } 1033 }
1029 1034
1030 if (G1Log::finest()) { 1035 if (G1Log::finest()) {
1031 buf.append_and_print_cr(""); 1036 buf.append_and_print_cr("");
1032 } 1037 }
1033 double avg = total / (double) no_of_gc_threads(); 1038 double avg = total / (double) no_of_gc_threads();
1034 buf.append_and_print_cr(" Avg: %.1lf Min: %.1lf Max: %.1lf Diff: %.1lf]", 1039 if (showDecimals) {
1035 avg, min, max, max - min); 1040 buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
1036 } 1041 min, avg, max, max - min, total);
1037 1042 } else {
1038 void G1CollectorPolicy::print_par_sizes(int level, 1043 buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
1039 const char* str, 1044 (int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
1040 double* data) { 1045 }
1041 double min = data[0], max = data[0];
1042 double total = 0.0;
1043 LineBuffer buf(level);
1044 buf.append("[%s :", str);
1045 for (uint i = 0; i < no_of_gc_threads(); ++i) {
1046 double val = data[i];
1047 if (val < min)
1048 min = val;
1049 if (val > max)
1050 max = val;
1051 total += val;
1052 buf.append(" %d", (int) val);
1053 }
1054 buf.append_and_print_cr("");
1055 double avg = total / (double) no_of_gc_threads();
1056 buf.append_and_print_cr(" Sum: %d, Avg: %d, Min: %d, Max: %d, Diff: %d]",
1057 (int)total, (int)avg, (int)min, (int)max, (int)max - (int)min);
1058 } 1046 }
1059 1047
1060 void G1CollectorPolicy::print_stats(int level, 1048 void G1CollectorPolicy::print_stats(int level,
1061 const char* str, 1049 const char* str,
1062 double value) { 1050 double value) {
1063 LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value); 1051 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
1052 }
1053
1054 void G1CollectorPolicy::print_stats(int level,
1055 const char* str,
1056 double value,
1057 int workers) {
1058 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
1064 } 1059 }
1065 1060
1066 void G1CollectorPolicy::print_stats(int level, 1061 void G1CollectorPolicy::print_stats(int level,
1067 const char* str, 1062 const char* str,
1068 int value) { 1063 int value) {
1371 1366
1372 if (_root_region_scan_wait_time_ms > 0.0) { 1367 if (_root_region_scan_wait_time_ms > 0.0) {
1373 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); 1368 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1374 } 1369 }
1375 if (parallel) { 1370 if (parallel) {
1376 print_stats(1, "Parallel Time", _cur_collection_par_time_ms); 1371 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads);
1377 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms); 1372 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1378 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); 1373 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1379 if (print_marking_info) { 1374 if (print_marking_info) {
1380 print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms); 1375 print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1381 } 1376 }
1382 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); 1377 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1383 if (G1Log::finest()) { 1378 if (G1Log::finest()) {
1384 print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers); 1379 print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
1380 false /* showDecimals */);
1385 } 1381 }
1386 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); 1382 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
1387 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); 1383 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
1388 print_par_stats(2, "Termination", _par_last_termination_times_ms); 1384 print_par_stats(2, "Termination", _par_last_termination_times_ms);
1389 if (G1Log::finest()) { 1385 if (G1Log::finest()) {
1390 print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts); 1386 print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
1387 false /* showDecimals */);
1391 } 1388 }
1392 1389
1393 for (int i = 0; i < _parallel_gc_threads; i++) { 1390 for (int i = 0; i < _parallel_gc_threads; i++) {
1394 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - 1391 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
1395 _par_last_gc_worker_start_times_ms[i]; 1392 _par_last_gc_worker_start_times_ms[i];
1599 adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms); 1596 adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms);
1600 1597
1601 _collectionSetChooser->verify(); 1598 _collectionSetChooser->verify();
1602 } 1599 }
1603 1600
1604 #define EXT_SIZE_FORMAT "%d%s" 1601 #define EXT_SIZE_FORMAT "%.1f%s"
1605 #define EXT_SIZE_PARAMS(bytes) \ 1602 #define EXT_SIZE_PARAMS(bytes) \
1606 byte_size_in_proper_unit((bytes)), \ 1603 byte_size_in_proper_unit((double)(bytes)), \
1607 proper_unit_for_byte_size((bytes)) 1604 proper_unit_for_byte_size((bytes))
1608 1605
1609 void G1CollectorPolicy::print_heap_transition() { 1606 void G1CollectorPolicy::print_heap_transition() {
1610 if (G1Log::finer()) { 1607 if (G1Log::finer()) {
1611 YoungList* young_list = _g1->young_list(); 1608 YoungList* young_list = _g1->young_list();