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 }
