Mercurial > hg > truffle
comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 2363:c93aa6caa02f
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 |