Mercurial > hg > truffle
comparison src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp @ 6628:bb3f6194fedb
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
Summary: Also reviewed by vitalyd@gmail.com. Introduced the WorkerDataArray class. Fixed some minor logging bugs.
Reviewed-by: johnc, mgerdin
author | brutisso |
---|---|
date | Thu, 23 Aug 2012 10:21:12 +0200 |
parents | 922993931b3d |
children | 5baec2e69518 |
comparison
equal
deleted
inserted
replaced
6625:153776c4cb6f | 6628:bb3f6194fedb |
---|---|
77 gclog_or_tty->print_cr("%s", _buffer); | 77 gclog_or_tty->print_cr("%s", _buffer); |
78 _cur = _indent_level * INDENT_CHARS; | 78 _cur = _indent_level * INDENT_CHARS; |
79 } | 79 } |
80 }; | 80 }; |
81 | 81 |
82 template <class T> | |
83 void WorkerDataArray<T>::print(int level, const char* title) { | |
84 if (_length == 1) { | |
85 // No need for min, max, average and sum for only one worker | |
86 LineBuffer buf(level); | |
87 buf.append("[%s: ", title); | |
88 buf.append(_print_format, _data[0]); | |
89 buf.append_and_print_cr("]"); | |
90 return; | |
91 } | |
92 | |
93 T min = _data[0]; | |
94 T max = _data[0]; | |
95 T sum = 0; | |
96 | |
97 LineBuffer buf(level); | |
98 buf.append("[%s:", title); | |
99 for (uint i = 0; i < _length; ++i) { | |
100 T val = _data[i]; | |
101 min = MIN2(val, min); | |
102 max = MAX2(val, max); | |
103 sum += val; | |
104 if (G1Log::finest()) { | |
105 buf.append(" "); | |
106 buf.append(_print_format, val); | |
107 } | |
108 } | |
109 | |
110 if (G1Log::finest()) { | |
111 buf.append_and_print_cr(""); | |
112 } | |
113 | |
114 double avg = (double)sum / (double)_length; | |
115 buf.append(" Min: "); | |
116 buf.append(_print_format, min); | |
117 buf.append(", Avg: "); | |
118 buf.append("%.1lf", avg); // Always print average as a double | |
119 buf.append(", Max: "); | |
120 buf.append(_print_format, max); | |
121 buf.append(", Diff: "); | |
122 buf.append(_print_format, max - min); | |
123 if (_print_sum) { | |
124 // for things like the start and end times the sum is not | |
125 // that relevant | |
126 buf.append(", Sum: "); | |
127 buf.append(_print_format, sum); | |
128 } | |
129 buf.append_and_print_cr("]"); | |
130 } | |
131 | |
132 #ifdef ASSERT | |
133 | |
134 template <class T> | |
135 void WorkerDataArray<T>::reset() { | |
136 for (uint i = 0; i < _length; i++) { | |
137 _data[i] = (T)-1; | |
138 } | |
139 } | |
140 | |
141 template <class T> | |
142 void WorkerDataArray<T>::verify() { | |
143 for (uint i = 0; i < _length; i++) { | |
144 assert(_data[i] >= (T)0, err_msg("Invalid data for worker %d", i)); | |
145 } | |
146 } | |
147 | |
148 #endif | |
149 | |
82 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : | 150 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : |
83 _max_gc_threads(max_gc_threads), | 151 _max_gc_threads(max_gc_threads), |
84 _min_clear_cc_time_ms(-1.0), | 152 _min_clear_cc_time_ms(-1.0), |
85 _max_clear_cc_time_ms(-1.0), | 153 _max_clear_cc_time_ms(-1.0), |
86 _cur_clear_cc_time_ms(0.0), | 154 _cur_clear_cc_time_ms(0.0), |
87 _cum_clear_cc_time_ms(0.0), | 155 _cum_clear_cc_time_ms(0.0), |
88 _num_cc_clears(0L) | 156 _num_cc_clears(0L), |
157 _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false), | |
158 _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"), | |
159 _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"), | |
160 _last_update_rs_times_ms(_max_gc_threads, "%.1lf"), | |
161 _last_update_rs_processed_buffers(_max_gc_threads, "%d"), | |
162 _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"), | |
163 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"), | |
164 _last_termination_times_ms(_max_gc_threads, "%.1lf"), | |
165 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT), | |
166 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false), | |
167 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"), | |
168 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf") | |
89 { | 169 { |
90 assert(max_gc_threads > 0, "Must have some GC threads"); | 170 assert(max_gc_threads > 0, "Must have some GC threads"); |
91 _par_last_gc_worker_start_times_ms = new double[_max_gc_threads]; | 171 } |
92 _par_last_ext_root_scan_times_ms = new double[_max_gc_threads]; | 172 |
93 _par_last_satb_filtering_times_ms = new double[_max_gc_threads]; | 173 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { |
94 _par_last_update_rs_times_ms = new double[_max_gc_threads]; | |
95 _par_last_update_rs_processed_buffers = new double[_max_gc_threads]; | |
96 _par_last_scan_rs_times_ms = new double[_max_gc_threads]; | |
97 _par_last_obj_copy_times_ms = new double[_max_gc_threads]; | |
98 _par_last_termination_times_ms = new double[_max_gc_threads]; | |
99 _par_last_termination_attempts = new double[_max_gc_threads]; | |
100 _par_last_gc_worker_end_times_ms = new double[_max_gc_threads]; | |
101 _par_last_gc_worker_times_ms = new double[_max_gc_threads]; | |
102 _par_last_gc_worker_other_times_ms = new double[_max_gc_threads]; | |
103 } | |
104 | |
105 void G1GCPhaseTimes::note_gc_start(double pause_start_time_sec, uint active_gc_threads, | |
106 bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause) { | |
107 assert(active_gc_threads > 0, "The number of threads must be > 0"); | 174 assert(active_gc_threads > 0, "The number of threads must be > 0"); |
108 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads"); | 175 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads"); |
109 _active_gc_threads = active_gc_threads; | 176 _active_gc_threads = active_gc_threads; |
110 _pause_start_time_sec = pause_start_time_sec; | 177 |
111 _is_young_gc = is_young_gc; | 178 _last_gc_worker_start_times_ms.reset(); |
112 _is_initial_mark_gc = is_initial_mark_gc; | 179 _last_ext_root_scan_times_ms.reset(); |
113 _gc_cause = gc_cause; | 180 _last_satb_filtering_times_ms.reset(); |
114 | 181 _last_update_rs_times_ms.reset(); |
115 #ifdef ASSERT | 182 _last_update_rs_processed_buffers.reset(); |
116 // initialise the timing data to something well known so that we can spot | 183 _last_scan_rs_times_ms.reset(); |
117 // if something is not set properly | 184 _last_obj_copy_times_ms.reset(); |
118 | 185 _last_termination_times_ms.reset(); |
119 for (uint i = 0; i < _max_gc_threads; ++i) { | 186 _last_termination_attempts.reset(); |
120 _par_last_gc_worker_start_times_ms[i] = -1234.0; | 187 _last_gc_worker_end_times_ms.reset(); |
121 _par_last_ext_root_scan_times_ms[i] = -1234.0; | 188 _last_gc_worker_times_ms.reset(); |
122 _par_last_satb_filtering_times_ms[i] = -1234.0; | 189 _last_gc_worker_other_times_ms.reset(); |
123 _par_last_update_rs_times_ms[i] = -1234.0; | 190 } |
124 _par_last_update_rs_processed_buffers[i] = -1234.0; | 191 |
125 _par_last_scan_rs_times_ms[i] = -1234.0; | 192 void G1GCPhaseTimes::note_gc_end() { |
126 _par_last_obj_copy_times_ms[i] = -1234.0; | 193 _last_gc_worker_start_times_ms.verify(); |
127 _par_last_termination_times_ms[i] = -1234.0; | 194 _last_ext_root_scan_times_ms.verify(); |
128 _par_last_termination_attempts[i] = -1234.0; | 195 _last_satb_filtering_times_ms.verify(); |
129 _par_last_gc_worker_end_times_ms[i] = -1234.0; | 196 _last_update_rs_times_ms.verify(); |
130 _par_last_gc_worker_times_ms[i] = -1234.0; | 197 _last_update_rs_processed_buffers.verify(); |
131 _par_last_gc_worker_other_times_ms[i] = -1234.0; | 198 _last_scan_rs_times_ms.verify(); |
132 } | 199 _last_obj_copy_times_ms.verify(); |
133 #endif | 200 _last_termination_times_ms.verify(); |
134 } | 201 _last_termination_attempts.verify(); |
135 | 202 _last_gc_worker_end_times_ms.verify(); |
136 void G1GCPhaseTimes::note_gc_end(double pause_end_time_sec) { | |
137 if (G1Log::fine()) { | |
138 double pause_time_ms = (pause_end_time_sec - _pause_start_time_sec) * MILLIUNITS; | |
139 | 203 |
140 for (uint i = 0; i < _active_gc_threads; i++) { | 204 for (uint i = 0; i < _active_gc_threads; i++) { |
141 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - | 205 double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i); |
142 _par_last_gc_worker_start_times_ms[i]; | 206 _last_gc_worker_times_ms.set(i, worker_time); |
143 | 207 |
144 double worker_known_time = _par_last_ext_root_scan_times_ms[i] + | 208 double worker_known_time = _last_ext_root_scan_times_ms.get(i) + |
145 _par_last_satb_filtering_times_ms[i] + | 209 _last_satb_filtering_times_ms.get(i) + |
146 _par_last_update_rs_times_ms[i] + | 210 _last_update_rs_times_ms.get(i) + |
147 _par_last_scan_rs_times_ms[i] + | 211 _last_scan_rs_times_ms.get(i) + |
148 _par_last_obj_copy_times_ms[i] + | 212 _last_obj_copy_times_ms.get(i) + |
149 _par_last_termination_times_ms[i]; | 213 _last_termination_times_ms.get(i); |
150 | 214 |
151 _par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] - | 215 double worker_other_time = worker_time - worker_known_time; |
152 worker_known_time; | 216 _last_gc_worker_other_times_ms.set(i, worker_other_time); |
153 } | 217 } |
154 | 218 |
155 print(pause_time_ms); | 219 _last_gc_worker_times_ms.verify(); |
156 } | 220 _last_gc_worker_other_times_ms.verify(); |
157 | |
158 } | |
159 | |
160 void G1GCPhaseTimes::print_par_stats(int level, | |
161 const char* str, | |
162 double* data, | |
163 bool showDecimals) { | |
164 double min = data[0], max = data[0]; | |
165 double total = 0.0; | |
166 LineBuffer buf(level); | |
167 buf.append("[%s (ms):", str); | |
168 for (uint i = 0; i < _active_gc_threads; ++i) { | |
169 double val = data[i]; | |
170 if (val < min) | |
171 min = val; | |
172 if (val > max) | |
173 max = val; | |
174 total += val; | |
175 if (G1Log::finest()) { | |
176 if (showDecimals) { | |
177 buf.append(" %.1lf", val); | |
178 } else { | |
179 buf.append(" %d", (int)val); | |
180 } | |
181 } | |
182 } | |
183 | |
184 if (G1Log::finest()) { | |
185 buf.append_and_print_cr(""); | |
186 } | |
187 double avg = total / (double) _active_gc_threads; | |
188 if (showDecimals) { | |
189 buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]", | |
190 min, avg, max, max - min, total); | |
191 } else { | |
192 buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]", | |
193 (int)min, (int)avg, (int)max, (int)max - (int)min, (int)total); | |
194 } | |
195 } | 221 } |
196 | 222 |
197 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) { | 223 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) { |
198 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value); | 224 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value); |
199 } | 225 } |
200 | 226 |
201 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int workers) { | 227 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int workers) { |
202 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers); | 228 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers); |
203 } | |
204 | |
205 void G1GCPhaseTimes::print_stats(int level, const char* str, int value) { | |
206 LineBuffer(level).append_and_print_cr("[%s: %d]", str, value); | |
207 } | |
208 | |
209 double G1GCPhaseTimes::avg_value(double* data) { | |
210 if (G1CollectedHeap::use_parallel_gc_threads()) { | |
211 double ret = 0.0; | |
212 for (uint i = 0; i < _active_gc_threads; ++i) { | |
213 ret += data[i]; | |
214 } | |
215 return ret / (double) _active_gc_threads; | |
216 } else { | |
217 return data[0]; | |
218 } | |
219 } | |
220 | |
221 double G1GCPhaseTimes::max_value(double* data) { | |
222 if (G1CollectedHeap::use_parallel_gc_threads()) { | |
223 double ret = data[0]; | |
224 for (uint i = 1; i < _active_gc_threads; ++i) { | |
225 if (data[i] > ret) { | |
226 ret = data[i]; | |
227 } | |
228 } | |
229 return ret; | |
230 } else { | |
231 return data[0]; | |
232 } | |
233 } | |
234 | |
235 double G1GCPhaseTimes::sum_of_values(double* data) { | |
236 if (G1CollectedHeap::use_parallel_gc_threads()) { | |
237 double sum = 0.0; | |
238 for (uint i = 0; i < _active_gc_threads; i++) { | |
239 sum += data[i]; | |
240 } | |
241 return sum; | |
242 } else { | |
243 return data[0]; | |
244 } | |
245 } | |
246 | |
247 double G1GCPhaseTimes::max_sum(double* data1, double* data2) { | |
248 double ret = data1[0] + data2[0]; | |
249 | |
250 if (G1CollectedHeap::use_parallel_gc_threads()) { | |
251 for (uint i = 1; i < _active_gc_threads; ++i) { | |
252 double data = data1[i] + data2[i]; | |
253 if (data > ret) { | |
254 ret = data; | |
255 } | |
256 } | |
257 } | |
258 return ret; | |
259 } | |
260 | |
261 void G1GCPhaseTimes::collapse_par_times() { | |
262 _ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms); | |
263 _satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms); | |
264 _update_rs_time = avg_value(_par_last_update_rs_times_ms); | |
265 _update_rs_processed_buffers = | |
266 sum_of_values(_par_last_update_rs_processed_buffers); | |
267 _scan_rs_time = avg_value(_par_last_scan_rs_times_ms); | |
268 _obj_copy_time = avg_value(_par_last_obj_copy_times_ms); | |
269 _termination_time = avg_value(_par_last_termination_times_ms); | |
270 } | 229 } |
271 | 230 |
272 double G1GCPhaseTimes::accounted_time_ms() { | 231 double G1GCPhaseTimes::accounted_time_ms() { |
273 // Subtract the root region scanning wait time. It's initialized to | 232 // Subtract the root region scanning wait time. It's initialized to |
274 // zero at the start of the pause. | 233 // zero at the start of the pause. |
284 misc_time_ms += _cur_clear_ct_time_ms; | 243 misc_time_ms += _cur_clear_ct_time_ms; |
285 | 244 |
286 return misc_time_ms; | 245 return misc_time_ms; |
287 } | 246 } |
288 | 247 |
289 void G1GCPhaseTimes::print(double pause_time_ms) { | 248 void G1GCPhaseTimes::print(double pause_time_sec) { |
290 | |
291 if (PrintGCTimeStamps) { | |
292 gclog_or_tty->stamp(); | |
293 gclog_or_tty->print(": "); | |
294 } | |
295 | |
296 GCCauseString gc_cause_str = GCCauseString("GC pause", _gc_cause) | |
297 .append(_is_young_gc ? " (young)" : " (mixed)") | |
298 .append(_is_initial_mark_gc ? " (initial-mark)" : ""); | |
299 gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_ms / 1000.0); | |
300 | |
301 if (!G1Log::finer()) { | |
302 return; | |
303 } | |
304 | |
305 if (_root_region_scan_wait_time_ms > 0.0) { | 249 if (_root_region_scan_wait_time_ms > 0.0) { |
306 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); | 250 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); |
307 } | 251 } |
308 if (G1CollectedHeap::use_parallel_gc_threads()) { | 252 if (G1CollectedHeap::use_parallel_gc_threads()) { |
309 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads); | 253 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads); |
310 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms); | 254 _last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)"); |
311 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); | 255 _last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)"); |
312 if (_satb_filtering_time > 0.0) { | 256 if (_last_satb_filtering_times_ms.sum() > 0.0) { |
313 print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms); | 257 _last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)"); |
314 } | 258 } |
315 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); | 259 _last_update_rs_times_ms.print(2, "Update RS (ms)"); |
260 _last_update_rs_processed_buffers.print(3, "Processed Buffers"); | |
261 _last_scan_rs_times_ms.print(2, "Scan RS (ms)"); | |
262 _last_obj_copy_times_ms.print(2, "Object Copy (ms)"); | |
263 _last_termination_times_ms.print(2, "Termination (ms)"); | |
316 if (G1Log::finest()) { | 264 if (G1Log::finest()) { |
317 print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers, | 265 _last_termination_attempts.print(3, "Termination Attempts"); |
318 false /* showDecimals */); | 266 } |
319 } | 267 _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)"); |
320 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); | 268 _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)"); |
321 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); | 269 _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)"); |
322 print_par_stats(2, "Termination", _par_last_termination_times_ms); | |
323 if (G1Log::finest()) { | |
324 print_par_stats(3, "Termination Attempts", _par_last_termination_attempts, | |
325 false /* showDecimals */); | |
326 } | |
327 print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms); | |
328 print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms); | |
329 print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms); | |
330 } else { | 270 } else { |
331 print_stats(1, "Ext Root Scanning", _ext_root_scan_time); | 271 _last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)"); |
332 if (_satb_filtering_time > 0.0) { | 272 if (_last_satb_filtering_times_ms.sum() > 0.0) { |
333 print_stats(1, "SATB Filtering", _satb_filtering_time); | 273 _last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)"); |
334 } | 274 } |
335 print_stats(1, "Update RS", _update_rs_time); | 275 _last_update_rs_times_ms.print(1, "Update RS (ms)"); |
336 if (G1Log::finest()) { | 276 _last_update_rs_processed_buffers.print(2, "Processed Buffers"); |
337 print_stats(2, "Processed Buffers", (int)_update_rs_processed_buffers); | 277 _last_scan_rs_times_ms.print(1, "Scan RS (ms)"); |
338 } | 278 _last_obj_copy_times_ms.print(1, "Object Copy (ms)"); |
339 print_stats(1, "Scan RS", _scan_rs_time); | |
340 print_stats(1, "Object Copying", _obj_copy_time); | |
341 } | 279 } |
342 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); | 280 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); |
343 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); | 281 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); |
344 if (Verbose && G1Log::finest()) { | 282 if (Verbose && G1Log::finest()) { |
345 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); | 283 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); |
348 print_stats(1, "Max Clear CC", _max_clear_cc_time_ms); | 286 print_stats(1, "Max Clear CC", _max_clear_cc_time_ms); |
349 if (_num_cc_clears > 0) { | 287 if (_num_cc_clears > 0) { |
350 print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears)); | 288 print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears)); |
351 } | 289 } |
352 } | 290 } |
353 double misc_time_ms = pause_time_ms - accounted_time_ms(); | 291 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms(); |
354 print_stats(1, "Other", misc_time_ms); | 292 print_stats(1, "Other", misc_time_ms); |
293 if (_cur_verify_before_time_ms > 0.0) { | |
294 print_stats(2, "Verify Before", _cur_verify_before_time_ms); | |
295 } | |
355 print_stats(2, "Choose CSet", | 296 print_stats(2, "Choose CSet", |
356 (_recorded_young_cset_choice_time_ms + | 297 (_recorded_young_cset_choice_time_ms + |
357 _recorded_non_young_cset_choice_time_ms)); | 298 _recorded_non_young_cset_choice_time_ms)); |
358 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms); | 299 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms); |
359 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms); | 300 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms); |
360 print_stats(2, "Free CSet", | 301 print_stats(2, "Free CSet", |
361 (_recorded_young_free_cset_time_ms + | 302 (_recorded_young_free_cset_time_ms + |
362 _recorded_non_young_free_cset_time_ms)); | 303 _recorded_non_young_free_cset_time_ms)); |
304 if (_cur_verify_after_time_ms > 0.0) { | |
305 print_stats(2, "Verify After", _cur_verify_after_time_ms); | |
306 } | |
363 } | 307 } |
364 | 308 |
365 void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) { | 309 void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) { |
366 if (!(Verbose && G1Log::finest())) { | 310 if (!(Verbose && G1Log::finest())) { |
367 return; | 311 return; |