Thu, 03 Mar 2011 22:58:46 +0100
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
src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp | file | annotate | diff | comparison | revisions |
1.1 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Sun Mar 06 11:37:18 2011 -0800 1.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Thu Mar 03 22:58:46 2011 +0100 1.3 @@ -81,6 +81,57 @@ 1.4 1.5 // </NEW PREDICTION> 1.6 1.7 +// Help class for avoiding interleaved logging 1.8 +class LineBuffer: public StackObj { 1.9 + 1.10 +private: 1.11 + static const int BUFFER_LEN = 1024; 1.12 + static const int INDENT_CHARS = 3; 1.13 + char _buffer[BUFFER_LEN]; 1.14 + int _indent_level; 1.15 + int _cur; 1.16 + 1.17 + void vappend(const char* format, va_list ap) { 1.18 + int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap); 1.19 + if (res != -1) { 1.20 + _cur += res; 1.21 + } else { 1.22 + DEBUG_ONLY(warning("buffer too small in LineBuffer");) 1.23 + _buffer[BUFFER_LEN -1] = 0; 1.24 + _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again 1.25 + } 1.26 + } 1.27 + 1.28 +public: 1.29 + explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) { 1.30 + for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) { 1.31 + _buffer[_cur] = ' '; 1.32 + } 1.33 + } 1.34 + 1.35 +#ifndef PRODUCT 1.36 + ~LineBuffer() { 1.37 + assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?"); 1.38 + } 1.39 +#endif 1.40 + 1.41 + void append(const char* format, ...) { 1.42 + va_list ap; 1.43 + va_start(ap, format); 1.44 + vappend(format, ap); 1.45 + va_end(ap); 1.46 + } 1.47 + 1.48 + void append_and_print_cr(const char* format, ...) { 1.49 + va_list ap; 1.50 + va_start(ap, format); 1.51 + vappend(format, ap); 1.52 + va_end(ap); 1.53 + gclog_or_tty->print_cr("%s", _buffer); 1.54 + _cur = _indent_level * INDENT_CHARS; 1.55 + } 1.56 +}; 1.57 + 1.58 G1CollectorPolicy::G1CollectorPolicy() : 1.59 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() 1.60 ? ParallelGCThreads : 1), 1.61 @@ -1016,10 +1067,8 @@ 1.62 bool summary) { 1.63 double min = data[0], max = data[0]; 1.64 double total = 0.0; 1.65 - int j; 1.66 - for (j = 0; j < level; ++j) 1.67 - gclog_or_tty->print(" "); 1.68 - gclog_or_tty->print("[%s (ms):", str); 1.69 + LineBuffer buf(level); 1.70 + buf.append("[%s (ms):", str); 1.71 for (uint i = 0; i < ParallelGCThreads; ++i) { 1.72 double val = data[i]; 1.73 if (val < min) 1.74 @@ -1027,18 +1076,16 @@ 1.75 if (val > max) 1.76 max = val; 1.77 total += val; 1.78 - gclog_or_tty->print(" %3.1lf", val); 1.79 + buf.append(" %3.1lf", val); 1.80 } 1.81 if (summary) { 1.82 - gclog_or_tty->print_cr(""); 1.83 + buf.append_and_print_cr(""); 1.84 double avg = total / (double) ParallelGCThreads; 1.85 - gclog_or_tty->print(" "); 1.86 - for (j = 0; j < level; ++j) 1.87 - gclog_or_tty->print(" "); 1.88 - gclog_or_tty->print("Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf", 1.89 + buf.append(" "); 1.90 + buf.append("Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf", 1.91 avg, min, max); 1.92 } 1.93 - gclog_or_tty->print_cr("]"); 1.94 + buf.append_and_print_cr("]"); 1.95 } 1.96 1.97 void G1CollectorPolicy::print_par_sizes(int level, 1.98 @@ -1047,10 +1094,8 @@ 1.99 bool summary) { 1.100 double min = data[0], max = data[0]; 1.101 double total = 0.0; 1.102 - int j; 1.103 - for (j = 0; j < level; ++j) 1.104 - gclog_or_tty->print(" "); 1.105 - gclog_or_tty->print("[%s :", str); 1.106 + LineBuffer buf(level); 1.107 + buf.append("[%s :", str); 1.108 for (uint i = 0; i < ParallelGCThreads; ++i) { 1.109 double val = data[i]; 1.110 if (val < min) 1.111 @@ -1058,34 +1103,28 @@ 1.112 if (val > max) 1.113 max = val; 1.114 total += val; 1.115 - gclog_or_tty->print(" %d", (int) val); 1.116 + buf.append(" %d", (int) val); 1.117 } 1.118 if (summary) { 1.119 - gclog_or_tty->print_cr(""); 1.120 + buf.append_and_print_cr(""); 1.121 double avg = total / (double) ParallelGCThreads; 1.122 - gclog_or_tty->print(" "); 1.123 - for (j = 0; j < level; ++j) 1.124 - gclog_or_tty->print(" "); 1.125 - gclog_or_tty->print("Sum: %d, Avg: %d, Min: %d, Max: %d", 1.126 + buf.append(" "); 1.127 + buf.append("Sum: %d, Avg: %d, Min: %d, Max: %d", 1.128 (int)total, (int)avg, (int)min, (int)max); 1.129 } 1.130 - gclog_or_tty->print_cr("]"); 1.131 + buf.append_and_print_cr("]"); 1.132 } 1.133 1.134 void G1CollectorPolicy::print_stats (int level, 1.135 const char* str, 1.136 double value) { 1.137 - for (int j = 0; j < level; ++j) 1.138 - gclog_or_tty->print(" "); 1.139 - gclog_or_tty->print_cr("[%s: %5.1lf ms]", str, value); 1.140 + LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value); 1.141 } 1.142 1.143 void G1CollectorPolicy::print_stats (int level, 1.144 const char* str, 1.145 int value) { 1.146 - for (int j = 0; j < level; ++j) 1.147 - gclog_or_tty->print(" "); 1.148 - gclog_or_tty->print_cr("[%s: %d]", str, value); 1.149 + LineBuffer(level).append_and_print_cr("[%s: %d]", str, value); 1.150 } 1.151 1.152 double G1CollectorPolicy::avg_value (double* data) { 1.153 @@ -2060,17 +2099,11 @@ 1.154 _g1->collection_set_iterate(&cs_closure); 1.155 } 1.156 1.157 -static void print_indent(int level) { 1.158 - for (int j = 0; j < level+1; ++j) 1.159 - gclog_or_tty->print(" "); 1.160 -} 1.161 - 1.162 void G1CollectorPolicy::print_summary (int level, 1.163 const char* str, 1.164 NumberSeq* seq) const { 1.165 double sum = seq->sum(); 1.166 - print_indent(level); 1.167 - gclog_or_tty->print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", 1.168 + LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", 1.169 str, sum / 1000.0, seq->avg()); 1.170 } 1.171 1.172 @@ -2078,8 +2111,7 @@ 1.173 const char* str, 1.174 NumberSeq* seq) const { 1.175 print_summary(level, str, seq); 1.176 - print_indent(level + 5); 1.177 - gclog_or_tty->print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", 1.178 + LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", 1.179 seq->num(), seq->sd(), seq->maximum()); 1.180 } 1.181 1.182 @@ -2087,6 +2119,7 @@ 1.183 NumberSeq* other_times_ms, 1.184 NumberSeq* calc_other_times_ms) const { 1.185 bool should_print = false; 1.186 + LineBuffer buf(level + 2); 1.187 1.188 double max_sum = MAX2(fabs(other_times_ms->sum()), 1.189 fabs(calc_other_times_ms->sum())); 1.190 @@ -2095,8 +2128,7 @@ 1.191 double sum_ratio = max_sum / min_sum; 1.192 if (sum_ratio > 1.1) { 1.193 should_print = true; 1.194 - print_indent(level + 1); 1.195 - gclog_or_tty->print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###"); 1.196 + buf.append_and_print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###"); 1.197 } 1.198 1.199 double max_avg = MAX2(fabs(other_times_ms->avg()), 1.200 @@ -2106,30 +2138,25 @@ 1.201 double avg_ratio = max_avg / min_avg; 1.202 if (avg_ratio > 1.1) { 1.203 should_print = true; 1.204 - print_indent(level + 1); 1.205 - gclog_or_tty->print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###"); 1.206 + buf.append_and_print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###"); 1.207 } 1.208 1.209 if (other_times_ms->sum() < -0.01) { 1.210 - print_indent(level + 1); 1.211 - gclog_or_tty->print_cr("## RECORDED OTHER SUM IS NEGATIVE ###"); 1.212 + buf.append_and_print_cr("## RECORDED OTHER SUM IS NEGATIVE ###"); 1.213 } 1.214 1.215 if (other_times_ms->avg() < -0.01) { 1.216 - print_indent(level + 1); 1.217 - gclog_or_tty->print_cr("## RECORDED OTHER AVG IS NEGATIVE ###"); 1.218 + buf.append_and_print_cr("## RECORDED OTHER AVG IS NEGATIVE ###"); 1.219 } 1.220 1.221 if (calc_other_times_ms->sum() < -0.01) { 1.222 should_print = true; 1.223 - print_indent(level + 1); 1.224 - gclog_or_tty->print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###"); 1.225 + buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###"); 1.226 } 1.227 1.228 if (calc_other_times_ms->avg() < -0.01) { 1.229 should_print = true; 1.230 - print_indent(level + 1); 1.231 - gclog_or_tty->print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###"); 1.232 + buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###"); 1.233 } 1.234 1.235 if (should_print) 1.236 @@ -2210,10 +2237,9 @@ 1.237 } 1.238 } 1.239 } else { 1.240 - print_indent(0); 1.241 - gclog_or_tty->print_cr("none"); 1.242 + LineBuffer(1).append_and_print_cr("none"); 1.243 } 1.244 - gclog_or_tty->print_cr(""); 1.245 + LineBuffer(0).append_and_print_cr(""); 1.246 } 1.247 1.248 void G1CollectorPolicy::print_tracing_info() const { 1.249 @@ -2532,7 +2558,7 @@ 1.250 jint regions_added = parKnownGarbageCl.marked_regions_added(); 1.251 _hrSorted->incNumMarkedHeapRegions(regions_added); 1.252 if (G1PrintParCleanupStats) { 1.253 - gclog_or_tty->print(" Thread %d called %d times, added %d regions to list.\n", 1.254 + gclog_or_tty->print_cr(" Thread %d called %d times, added %d regions to list.", 1.255 i, parKnownGarbageCl.invokes(), regions_added); 1.256 } 1.257 }