Mercurial > hg > truffle

comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 2363:c93aa6caa02f

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
7022943: G1: improve logging to avoid interleaved numbers Summary: Introduced buffered loggging to make sure that log lines are logged one line at a time Reviewed-by: stefank, johnc, dsamersoff
author brutisso
date Thu, 03 Mar 2011 22:58:46 +0100
parents c33825b68624
children 5c0b591e1074
comparison
equal deleted inserted replaced
2362:a2c2eac1ca62 2363:c93aa6caa02f
79 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30 79 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30
80 }; 80 };
81 81
82 // </NEW PREDICTION> 82 // </NEW PREDICTION>
83 83
84 // Help class for avoiding interleaved logging
85 class LineBuffer: public StackObj {
86
87 private:
88 static const int BUFFER_LEN = 1024;
89 static const int INDENT_CHARS = 3;
90 char _buffer[BUFFER_LEN];
91 int _indent_level;
92 int _cur;
93
94 void vappend(const char* format, va_list ap) {
95 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
96 if (res != -1) {
97 _cur += res;
98 } else {
99 DEBUG_ONLY(warning("buffer too small in LineBuffer");)
100 _buffer[BUFFER_LEN -1] = 0;
101 _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
102 }
103 }
104
105 public:
106 explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
107 for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
108 _buffer[_cur] = ' ';
109 }
110 }
111
112 #ifndef PRODUCT
113 ~LineBuffer() {
114 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
115 }
116 #endif
117
118 void append(const char* format, ...) {
119 va_list ap;
120 va_start(ap, format);
121 vappend(format, ap);
122 va_end(ap);
123 }
124
125 void append_and_print_cr(const char* format, ...) {
126 va_list ap;
127 va_start(ap, format);
128 vappend(format, ap);
129 va_end(ap);
130 gclog_or_tty->print_cr("%s", _buffer);
131 _cur = _indent_level * INDENT_CHARS;
132 }
133 };
134
84 G1CollectorPolicy::G1CollectorPolicy() : 135 G1CollectorPolicy::G1CollectorPolicy() :
85 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() 136 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
86 ? ParallelGCThreads : 1), 137 ? ParallelGCThreads : 1),
87 138
88 139
1014 const char* str, 1065 const char* str,
1015 double* data, 1066 double* data,
1016 bool summary) { 1067 bool summary) {
1017 double min = data[0], max = data[0]; 1068 double min = data[0], max = data[0];
1018 double total = 0.0; 1069 double total = 0.0;
1019 int j; 1070 LineBuffer buf(level);
1020 for (j = 0; j < level; ++j) 1071 buf.append("[%s (ms):", str);
1021 gclog_or_tty->print(" ");
1022 gclog_or_tty->print("[%s (ms):", str);
1023 for (uint i = 0; i < ParallelGCThreads; ++i) { 1072 for (uint i = 0; i < ParallelGCThreads; ++i) {
1024 double val = data[i]; 1073 double val = data[i];
1025 if (val < min) 1074 if (val < min)
1026 min = val; 1075 min = val;
1027 if (val > max) 1076 if (val > max)
1028 max = val; 1077 max = val;
1029 total += val; 1078 total += val;
1030 gclog_or_tty->print(" %3.1lf", val); 1079 buf.append(" %3.1lf", val);
1031 } 1080 }
1032 if (summary) { 1081 if (summary) {
1033 gclog_or_tty->print_cr(""); 1082 buf.append_and_print_cr("");
1034 double avg = total / (double) ParallelGCThreads; 1083 double avg = total / (double) ParallelGCThreads;
1035 gclog_or_tty->print(" "); 1084 buf.append(" ");
1036 for (j = 0; j < level; ++j) 1085 buf.append("Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf",
1037 gclog_or_tty->print(" ");
1038 gclog_or_tty->print("Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf",
1039 avg, min, max); 1086 avg, min, max);
1040 } 1087 }
1041 gclog_or_tty->print_cr("]"); 1088 buf.append_and_print_cr("]");
1042 } 1089 }
1043 1090
1044 void G1CollectorPolicy::print_par_sizes(int level, 1091 void G1CollectorPolicy::print_par_sizes(int level,
1045 const char* str, 1092 const char* str,
1046 double* data, 1093 double* data,
1047 bool summary) { 1094 bool summary) {
1048 double min = data[0], max = data[0]; 1095 double min = data[0], max = data[0];
1049 double total = 0.0; 1096 double total = 0.0;
1050 int j; 1097 LineBuffer buf(level);
1051 for (j = 0; j < level; ++j) 1098 buf.append("[%s :", str);
1052 gclog_or_tty->print(" ");
1053 gclog_or_tty->print("[%s :", str);
1054 for (uint i = 0; i < ParallelGCThreads; ++i) { 1099 for (uint i = 0; i < ParallelGCThreads; ++i) {
1055 double val = data[i]; 1100 double val = data[i];
1056 if (val < min) 1101 if (val < min)
1057 min = val; 1102 min = val;
1058 if (val > max) 1103 if (val > max)
1059 max = val; 1104 max = val;
1060 total += val; 1105 total += val;
1061 gclog_or_tty->print(" %d", (int) val); 1106 buf.append(" %d", (int) val);
1062 } 1107 }
1063 if (summary) { 1108 if (summary) {
1064 gclog_or_tty->print_cr(""); 1109 buf.append_and_print_cr("");
1065 double avg = total / (double) ParallelGCThreads; 1110 double avg = total / (double) ParallelGCThreads;
1066 gclog_or_tty->print(" "); 1111 buf.append(" ");
1067 for (j = 0; j < level; ++j) 1112 buf.append("Sum: %d, Avg: %d, Min: %d, Max: %d",
1068 gclog_or_tty->print(" ");
1069 gclog_or_tty->print("Sum: %d, Avg: %d, Min: %d, Max: %d",
1070 (int)total, (int)avg, (int)min, (int)max); 1113 (int)total, (int)avg, (int)min, (int)max);
1071 } 1114 }
1072 gclog_or_tty->print_cr("]"); 1115 buf.append_and_print_cr("]");
1073 } 1116 }
1074 1117
1075 void G1CollectorPolicy::print_stats (int level, 1118 void G1CollectorPolicy::print_stats (int level,
1076 const char* str, 1119 const char* str,
1077 double value) { 1120 double value) {
1078 for (int j = 0; j < level; ++j) 1121 LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value);
1079 gclog_or_tty->print(" ");
1080 gclog_or_tty->print_cr("[%s: %5.1lf ms]", str, value);
1081 } 1122 }
1082 1123
1083 void G1CollectorPolicy::print_stats (int level, 1124 void G1CollectorPolicy::print_stats (int level,
1084 const char* str, 1125 const char* str,
1085 int value) { 1126 int value) {
1086 for (int j = 0; j < level; ++j) 1127 LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
1087 gclog_or_tty->print(" ");
1088 gclog_or_tty->print_cr("[%s: %d]", str, value);
1089 } 1128 }
1090 1129
1091 double G1CollectorPolicy::avg_value (double* data) { 1130 double G1CollectorPolicy::avg_value (double* data) {
1092 if (G1CollectedHeap::use_parallel_gc_threads()) { 1131 if (G1CollectedHeap::use_parallel_gc_threads()) {
1093 double ret = 0.0; 1132 double ret = 0.0;
2058 void G1CollectorPolicy::count_CS_bytes_used() { 2097 void G1CollectorPolicy::count_CS_bytes_used() {
2059 CountCSClosure cs_closure(this); 2098 CountCSClosure cs_closure(this);
2060 _g1->collection_set_iterate(&cs_closure); 2099 _g1->collection_set_iterate(&cs_closure);
2061 } 2100 }
2062 2101
2063 static void print_indent(int level) {
2064 for (int j = 0; j < level+1; ++j)
2065 gclog_or_tty->print(" ");
2066 }
2067
2068 void G1CollectorPolicy::print_summary (int level, 2102 void G1CollectorPolicy::print_summary (int level,
2069 const char* str, 2103 const char* str,
2070 NumberSeq* seq) const { 2104 NumberSeq* seq) const {
2071 double sum = seq->sum(); 2105 double sum = seq->sum();
2072 print_indent(level); 2106 LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
2073 gclog_or_tty->print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
2074 str, sum / 1000.0, seq->avg()); 2107 str, sum / 1000.0, seq->avg());
2075 } 2108 }
2076 2109
2077 void G1CollectorPolicy::print_summary_sd (int level, 2110 void G1CollectorPolicy::print_summary_sd (int level,
2078 const char* str, 2111 const char* str,
2079 NumberSeq* seq) const { 2112 NumberSeq* seq) const {
2080 print_summary(level, str, seq); 2113 print_summary(level, str, seq);
2081 print_indent(level + 5); 2114 LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
2082 gclog_or_tty->print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
2083 seq->num(), seq->sd(), seq->maximum()); 2115 seq->num(), seq->sd(), seq->maximum());
2084 } 2116 }
2085 2117
2086 void G1CollectorPolicy::check_other_times(int level, 2118 void G1CollectorPolicy::check_other_times(int level,
2087 NumberSeq* other_times_ms, 2119 NumberSeq* other_times_ms,
2088 NumberSeq* calc_other_times_ms) const { 2120 NumberSeq* calc_other_times_ms) const {
2089 bool should_print = false; 2121 bool should_print = false;
2122 LineBuffer buf(level + 2);
2090 2123
2091 double max_sum = MAX2(fabs(other_times_ms->sum()), 2124 double max_sum = MAX2(fabs(other_times_ms->sum()),
2092 fabs(calc_other_times_ms->sum())); 2125 fabs(calc_other_times_ms->sum()));
2093 double min_sum = MIN2(fabs(other_times_ms->sum()), 2126 double min_sum = MIN2(fabs(other_times_ms->sum()),
2094 fabs(calc_other_times_ms->sum())); 2127 fabs(calc_other_times_ms->sum()));
2095 double sum_ratio = max_sum / min_sum; 2128 double sum_ratio = max_sum / min_sum;
2096 if (sum_ratio > 1.1) { 2129 if (sum_ratio > 1.1) {
2097 should_print = true; 2130 should_print = true;
2098 print_indent(level + 1); 2131 buf.append_and_print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###");
2099 gclog_or_tty->print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###");
2100 } 2132 }
2101 2133
2102 double max_avg = MAX2(fabs(other_times_ms->avg()), 2134 double max_avg = MAX2(fabs(other_times_ms->avg()),
2103 fabs(calc_other_times_ms->avg())); 2135 fabs(calc_other_times_ms->avg()));
2104 double min_avg = MIN2(fabs(other_times_ms->avg()), 2136 double min_avg = MIN2(fabs(other_times_ms->avg()),
2105 fabs(calc_other_times_ms->avg())); 2137 fabs(calc_other_times_ms->avg()));
2106 double avg_ratio = max_avg / min_avg; 2138 double avg_ratio = max_avg / min_avg;
2107 if (avg_ratio > 1.1) { 2139 if (avg_ratio > 1.1) {
2108 should_print = true; 2140 should_print = true;
2109 print_indent(level + 1); 2141 buf.append_and_print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###");
2110 gclog_or_tty->print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###");
2111 } 2142 }
2112 2143
2113 if (other_times_ms->sum() < -0.01) { 2144 if (other_times_ms->sum() < -0.01) {
2114 print_indent(level + 1); 2145 buf.append_and_print_cr("## RECORDED OTHER SUM IS NEGATIVE ###");
2115 gclog_or_tty->print_cr("## RECORDED OTHER SUM IS NEGATIVE ###");
2116 } 2146 }
2117 2147
2118 if (other_times_ms->avg() < -0.01) { 2148 if (other_times_ms->avg() < -0.01) {
2119 print_indent(level + 1); 2149 buf.append_and_print_cr("## RECORDED OTHER AVG IS NEGATIVE ###");
2120 gclog_or_tty->print_cr("## RECORDED OTHER AVG IS NEGATIVE ###");
2121 } 2150 }
2122 2151
2123 if (calc_other_times_ms->sum() < -0.01) { 2152 if (calc_other_times_ms->sum() < -0.01) {
2124 should_print = true; 2153 should_print = true;
2125 print_indent(level + 1); 2154 buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
2126 gclog_or_tty->print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
2127 } 2155 }
2128 2156
2129 if (calc_other_times_ms->avg() < -0.01) { 2157 if (calc_other_times_ms->avg() < -0.01) {
2130 should_print = true; 2158 should_print = true;
2131 print_indent(level + 1); 2159 buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
2132 gclog_or_tty->print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
2133 } 2160 }
2134 2161
2135 if (should_print) 2162 if (should_print)
2136 print_summary(level, "Other(Calc)", calc_other_times_ms); 2163 print_summary(level, "Other(Calc)", calc_other_times_ms);
2137 } 2164 }
2208 } 2235 }
2209 check_other_times(1, summary->get_other_seq(), &calc_other_times_ms); 2236 check_other_times(1, summary->get_other_seq(), &calc_other_times_ms);
2210 } 2237 }
2211 } 2238 }
2212 } else { 2239 } else {
2213 print_indent(0); 2240 LineBuffer(1).append_and_print_cr("none");
2214 gclog_or_tty->print_cr("none"); 2241 }
2215 } 2242 LineBuffer(0).append_and_print_cr("");
2216 gclog_or_tty->print_cr("");
2217 } 2243 }
2218 2244
2219 void G1CollectorPolicy::print_tracing_info() const { 2245 void G1CollectorPolicy::print_tracing_info() const {
2220 if (TraceGen0Time) { 2246 if (TraceGen0Time) {
2221 gclog_or_tty->print_cr("ALL PAUSES"); 2247 gclog_or_tty->print_cr("ALL PAUSES");
2530 _g1->heap_region_par_iterate_chunked(&parKnownGarbageCl, i, 2556 _g1->heap_region_par_iterate_chunked(&parKnownGarbageCl, i,
2531 HeapRegion::InitialClaimValue); 2557 HeapRegion::InitialClaimValue);
2532 jint regions_added = parKnownGarbageCl.marked_regions_added(); 2558 jint regions_added = parKnownGarbageCl.marked_regions_added();
2533 _hrSorted->incNumMarkedHeapRegions(regions_added); 2559 _hrSorted->incNumMarkedHeapRegions(regions_added);
2534 if (G1PrintParCleanupStats) { 2560 if (G1PrintParCleanupStats) {
2535 gclog_or_tty->print(" Thread %d called %d times, added %d regions to list.\n", 2561 gclog_or_tty->print_cr(" Thread %d called %d times, added %d regions to list.",
2536 i, parKnownGarbageCl.invokes(), regions_added); 2562 i, parKnownGarbageCl.invokes(), regions_added);
2537 } 2563 }
2538 } 2564 }
2539 }; 2565 };
2540 2566