56 public:
57 explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
58 for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
59 _buffer[_cur] = ' ';
60 }
61 }
62
63 #ifndef PRODUCT
64 ~LineBuffer() {
65 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
66 }
67 #endif
68
69 void append(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
70 va_list ap;
71 va_start(ap, format);
72 vappend(format, ap);
73 va_end(ap);
74 }
75
76 void append_and_print_cr(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
77 va_list ap;
78 va_start(ap, format);
79 vappend(format, ap);
80 va_end(ap);
81 gclog_or_tty->print_cr("%s", _buffer);
82 _cur = _indent_level * INDENT_CHARS;
83 }
84 };
85
86 template <class T>
87 WorkerDataArray<T>::WorkerDataArray(uint length, const char* title, bool print_sum, int log_level, uint indent_level) :
88 _title(title), _length(0), _print_sum(print_sum), _log_level(log_level), _indent_level(indent_level),
89 _has_new_data(true), _sub_count(NULL), _enabled(true) {
90 assert(length > 0, "Must have some workers to store data for");
91 _length = length;
92 _data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
93 }
94
95 template <class T>
96 WorkerDataArray<T>::~WorkerDataArray() {
97 FREE_C_HEAP_ARRAY(T, _data);
98 }
99
100 template <>
101 void WorkerDataArray<double>::log_value(LineBuffer& buf, double value) {
102 buf.append("%.1lf", value * 1000);
103 }
104
105 template <>
106 void WorkerDataArray<size_t>::log_value(LineBuffer& buf, size_t value) {
107 buf.append(SIZE_FORMAT, value);
108 }
109
110 template <>
111 size_t WorkerDataArray<size_t>::uninitialized() {
112 return (size_t)-1;
113 }
114
115 template <>
116 double WorkerDataArray<double>::uninitialized() {
117 return -1.0;
118 }
119
120 template <class T>
121 void WorkerDataArray<T>::print() {
122 if (_log_level > G1Log::level() || !_enabled) {
123 return;
124 }
125
126 if (_length == 1) {
127 // No need for min, max, average and sum for only one worker
128 LineBuffer buf(_indent_level);
129 buf.append("[%s: ", _title);
130 log_value(buf, _data[0]);
131 buf.append_and_print_cr("]");
132 return;
133 }
134
135 T min = _data[0];
136 T max = _data[0];
137 T sum = 0;
138
139 LineBuffer buf(_indent_level);
140 buf.append("[%s:", _title);
141 for (uint i = 0; i < _length; ++i) {
142 T val = _data[i];
143 min = MIN2(val, min);
144 max = MAX2(val, max);
145 sum += val;
146 if (G1Log::finest()) {
147 buf.append(" ");
148 log_value(buf, val);
149 }
150 }
151
152 if (G1Log::finest()) {
153 buf.append_and_print_cr("%s", "");
154 }
155
156 double avg = (double)sum / (double)_length;
157 buf.append(" Min: ");
158 log_value(buf, min);
159 buf.append(", Avg: ");
160 buf.append("%.1lf", avg); // Always print average as a double
161 buf.append(", Max: ");
162 log_value(buf, max);
163 buf.append(", Diff: ");
164 log_value(buf, max - min);
165 if (_print_sum) {
166 // for things like the start and end times the sum is not
167 // that relevant
168 buf.append(", Sum: ");
169 log_value(buf, sum);
170 }
171 buf.append_and_print_cr("]");
172
173 if (_sub_count != NULL) {
174 _sub_count->print();
175 }
176 }
177
178 #ifndef PRODUCT
179
180 template <class T>
181 void WorkerDataArray<T>::reset() {
182 for (uint i = 0; i < _length; i++) {
183 _data[i] = WorkerDataArray<T>::uninitialized();
184 }
185 if (_sub_count != NULL) {
186 _sub_count->reset();
187 }
188 }
189
190 template <class T>
191 void WorkerDataArray<T>::verify() {
192 for (uint i = 0; i < _length; i++) {
193 assert(_data[i] != WorkerDataArray<T>::uninitialized(),
194 err_msg("Invalid data for worker %u in '%s'", i, _title));
195 }
196 if (_sub_count != NULL) {
197 _sub_count->verify();
198 }
199 }
200
228
229 _gc_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2);
230 _gc_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2);
231
232 _gc_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3);
233 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3);
234 _gc_phases[RedirtyCards]->link_sub_count_array(_redirtied_cards);
235 }
236
237 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress) {
238 assert(active_gc_threads > 0, "The number of threads must be > 0");
239 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
240 _active_gc_threads = active_gc_threads;
241
242 for (int i = 0; i < Sentinel; i++) {
243 _gc_phases[i]->reset();
244 }
245
246 _gc_phases[SATBFiltering]->set_enabled(mark_in_progress);
247
248 _gc_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled);
249 _gc_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled);
250 }
251
252 void G1GCPhaseTimes::note_gc_end() {
253 for (uint i = 0; i < _active_gc_threads; i++) {
254 double worker_time = _gc_phases[GCWorkerEnd]->get(i) - _gc_phases[GCWorkerStart]->get(i);
255 record_time(GCWorkerTotal, i , worker_time);
256
257 double worker_known_time =
258 _gc_phases[ExtRootScan]->get(i) +
259 _gc_phases[SATBFiltering]->get(i) +
260 _gc_phases[UpdateRS]->get(i) +
261 _gc_phases[ScanRS]->get(i) +
262 _gc_phases[CodeRoots]->get(i) +
263 _gc_phases[ObjCopy]->get(i) +
264 _gc_phases[Termination]->get(i);
265
266 record_time(Other, i, worker_time - worker_known_time);
267 }
268
269 for (int i = 0; i < Sentinel; i++) {
270 _gc_phases[i]->verify();
271 }
272 }
273
274 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
275 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
276 }
277
278 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
279 LineBuffer(level).append_and_print_cr("[%s: "SIZE_FORMAT"]", str, value);
280 }
281
282 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
283 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
284 }
285
286 double G1GCPhaseTimes::accounted_time_ms() {
292
293 // Now subtract the time taken to fix up roots in generated code
294 misc_time_ms += _cur_collection_code_root_fixup_time_ms;
295
296 // Strong code root purge time
297 misc_time_ms += _cur_strong_code_root_purge_time_ms;
298
299 if (G1StringDedup::is_enabled()) {
300 // String dedup fixup time
301 misc_time_ms += _cur_string_dedup_fixup_time_ms;
302 }
303
304 // Subtract the time taken to clean the card table from the
305 // current value of "other time"
306 misc_time_ms += _cur_clear_ct_time_ms;
307
308 return misc_time_ms;
309 }
310
311 void G1GCPhaseTimes::print(double pause_time_sec) {
312 if (_root_region_scan_wait_time_ms > 0.0) {
313 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
314 }
315
316 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
317 for (int i = 0; i <= GCMainPhasesLast; i++) {
318 _gc_phases[i]->print();
319 }
320
321 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
322 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
323 if (G1StringDedup::is_enabled()) {
324 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
325 for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
326 _gc_phases[i]->print();
327 }
328 }
329 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
330 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
331 print_stats(1, "Other", misc_time_ms);
332 if (_cur_verify_before_time_ms > 0.0) {
333 print_stats(2, "Verify Before", _cur_verify_before_time_ms);
334 }
335 if (G1CollectedHeap::heap()->evacuation_failed()) {
336 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
337 _cur_evac_fail_restore_remsets;
338 print_stats(2, "Evacuation Failure", evac_fail_handling);
339 if (G1Log::finest()) {
340 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
341 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
342 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
343 }
344 }
345 print_stats(2, "Choose CSet",
346 (_recorded_young_cset_choice_time_ms +
347 _recorded_non_young_cset_choice_time_ms));
348 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
349 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
350 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
351 _gc_phases[RedirtyCards]->print();
352 if (G1EagerReclaimHumongousObjects) {
353 print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
354 if (G1Log::finest()) {
355 print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
356 print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
357 }
358 print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
359 if (G1Log::finest()) {
360 print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
361 }
362 }
363 print_stats(2, "Free CSet",
364 (_recorded_young_free_cset_time_ms +
365 _recorded_non_young_free_cset_time_ms));
366 if (G1Log::finest()) {
367 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
368 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
369 }
370 if (_cur_verify_after_time_ms > 0.0) {
371 print_stats(2, "Verify After", _cur_verify_after_time_ms);
372 }
373 }
374
375 G1GCPhaseTimesTracker::G1GCPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCPhases phase, uint worker_id) :
376 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
377 _start_time = os::elapsedTime();
378 }
379
380 G1GCPhaseTimesTracker::~G1GCPhaseTimesTracker() {
381 _phase_times->record_time(_phase, _worker_id, os::elapsedTime() - _start_time);
382 }
|
56 public:
57 explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
58 for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
59 _buffer[_cur] = ' ';
60 }
61 }
62
63 #ifndef PRODUCT
64 ~LineBuffer() {
65 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
66 }
67 #endif
68
69 void append(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
70 va_list ap;
71 va_start(ap, format);
72 vappend(format, ap);
73 va_end(ap);
74 }
75
76 void print_cr() {
77 gclog_or_tty->print_cr("%s", _buffer);
78 _cur = _indent_level * INDENT_CHARS;
79 }
80
81 void append_and_print_cr(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
82 va_list ap;
83 va_start(ap, format);
84 vappend(format, ap);
85 va_end(ap);
86 print_cr();
87 }
88 };
89
90 template <class T>
91 WorkerDataArray<T>::WorkerDataArray(uint length, const char* title, bool print_sum, int log_level, uint indent_level) :
92 _title(title), _length(0), _print_sum(print_sum), _log_level(log_level), _indent_level(indent_level),
93 _has_new_data(true), _sub_count(NULL), _enabled(true) {
94 assert(length > 0, "Must have some workers to store data for");
95 _length = length;
96 _data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
97 }
98
99 template <class T>
100 WorkerDataArray<T>::~WorkerDataArray() {
101 FREE_C_HEAP_ARRAY(T, _data);
102 }
103
104 #ifndef PRODUCT
105
106 template <>
107 size_t WorkerDataArray<size_t>::uninitialized() {
108 return (size_t)-1;
109 }
110
111 template <>
112 double WorkerDataArray<double>::uninitialized() {
113 return -1.0;
114 }
115
116 template <class T>
117 void WorkerDataArray<T>::reset() {
118 for (uint i = 0; i < _length; i++) {
119 _data[i] = WorkerDataArray<T>::uninitialized();
120 }
121 if (_sub_count != NULL) {
122 _sub_count->reset();
123 }
124 }
125
126 template <class T>
127 void WorkerDataArray<T>::verify() {
128 for (uint i = 0; i < _length; i++) {
129 assert(_data[i] != WorkerDataArray<T>::uninitialized(),
130 err_msg("Invalid data for worker %u in '%s'", i, _title));
131 }
132 if (_sub_count != NULL) {
133 _sub_count->verify();
134 }
135 }
136
164
165 _gc_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2);
166 _gc_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2);
167
168 _gc_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3);
169 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3);
170 _gc_phases[RedirtyCards]->link_sub_count_array(_redirtied_cards);
171 }
172
173 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress) {
174 assert(active_gc_threads > 0, "The number of threads must be > 0");
175 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
176 _active_gc_threads = active_gc_threads;
177
178 for (int i = 0; i < Sentinel; i++) {
179 _gc_phases[i]->reset();
180 }
181
182 _gc_phases[SATBFiltering]->set_enabled(mark_in_progress);
183
184 _gc_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
185 _gc_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
186 }
187
188 void G1GCPhaseTimes::note_gc_end() {
189 for (uint i = 0; i < _active_gc_threads; i++) {
190 double worker_time = _gc_phases[GCWorkerEnd]->get(i) - _gc_phases[GCWorkerStart]->get(i);
191 record_time_secs(GCWorkerTotal, i , worker_time);
192
193 double worker_known_time =
194 _gc_phases[ExtRootScan]->get(i) +
195 _gc_phases[SATBFiltering]->get(i) +
196 _gc_phases[UpdateRS]->get(i) +
197 _gc_phases[ScanRS]->get(i) +
198 _gc_phases[CodeRoots]->get(i) +
199 _gc_phases[ObjCopy]->get(i) +
200 _gc_phases[Termination]->get(i);
201
202 record_time_secs(Other, i, worker_time - worker_known_time);
203 }
204
205 for (int i = 0; i < Sentinel; i++) {
206 _gc_phases[i]->verify();
207 }
208 }
209
210 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
211 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
212 }
213
214 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
215 LineBuffer(level).append_and_print_cr("[%s: "SIZE_FORMAT"]", str, value);
216 }
217
218 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
219 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
220 }
221
222 double G1GCPhaseTimes::accounted_time_ms() {
228
229 // Now subtract the time taken to fix up roots in generated code
230 misc_time_ms += _cur_collection_code_root_fixup_time_ms;
231
232 // Strong code root purge time
233 misc_time_ms += _cur_strong_code_root_purge_time_ms;
234
235 if (G1StringDedup::is_enabled()) {
236 // String dedup fixup time
237 misc_time_ms += _cur_string_dedup_fixup_time_ms;
238 }
239
240 // Subtract the time taken to clean the card table from the
241 // current value of "other time"
242 misc_time_ms += _cur_clear_ct_time_ms;
243
244 return misc_time_ms;
245 }
246
247 void G1GCPhaseTimes::print(double pause_time_sec) {
248 G1GCPhasePrinter phase_printer(this);
249
250 if (_root_region_scan_wait_time_ms > 0.0) {
251 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
252 }
253
254 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
255 for (int i = 0; i <= GCMainPhasesLast; i++) {
256 phase_printer.print((GCPhases) i);
257 }
258
259 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
260 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
261 if (G1StringDedup::is_enabled()) {
262 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
263 for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
264 phase_printer.print((GCPhases) i);
265 }
266 }
267 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
268 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
269 print_stats(1, "Other", misc_time_ms);
270 if (_cur_verify_before_time_ms > 0.0) {
271 print_stats(2, "Verify Before", _cur_verify_before_time_ms);
272 }
273 if (G1CollectedHeap::heap()->evacuation_failed()) {
274 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
275 _cur_evac_fail_restore_remsets;
276 print_stats(2, "Evacuation Failure", evac_fail_handling);
277 if (G1Log::finest()) {
278 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
279 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
280 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
281 }
282 }
283 print_stats(2, "Choose CSet",
284 (_recorded_young_cset_choice_time_ms +
285 _recorded_non_young_cset_choice_time_ms));
286 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
287 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
288 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
289 phase_printer.print(RedirtyCards);
290 if (G1EagerReclaimHumongousObjects) {
291 print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
292 if (G1Log::finest()) {
293 print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
294 print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
295 }
296 print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
297 if (G1Log::finest()) {
298 print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
299 }
300 }
301 print_stats(2, "Free CSet",
302 (_recorded_young_free_cset_time_ms +
303 _recorded_non_young_free_cset_time_ms));
304 if (G1Log::finest()) {
305 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
306 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
307 }
308 if (_cur_verify_after_time_ms > 0.0) {
309 print_stats(2, "Verify After", _cur_verify_after_time_ms);
310 }
311 }
312
313 G1GCPhaseTimesTracker::G1GCPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCPhases phase, uint worker_id) :
314 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
315 _start_time = os::elapsedTime();
316 }
317
318 G1GCPhaseTimesTracker::~G1GCPhaseTimesTracker() {
319 _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
320 }
321
322 void G1GCPhasePrinter::print_single_length(G1GCPhaseTimes::GCPhases phase_id, WorkerDataArray<double>* phase) {
323 // No need for min, max, average and sum for only one worker
324 LineBuffer buf(phase->_indent_level);
325 buf.append_and_print_cr("[%s: %.1lf]", phase->_title, _phase_times->get_time_ms(phase_id, 0));
326
327 if (phase->_sub_count != NULL) {
328 LineBuffer buf2(phase->_sub_count->_indent_level);
329 buf2.append_and_print_cr("[%s: "SIZE_FORMAT"]", phase->_sub_count->_title, _phase_times->sub_count_sum(phase_id));
330 }
331 }
332
333 void G1GCPhasePrinter::print_time_values(LineBuffer& buf, G1GCPhaseTimes::GCPhases phase_id, WorkerDataArray<double>* phase) {
334 for (uint i = 0; i < phase->_length; ++i) {
335 buf.append(" %.1lf", _phase_times->get_time_ms(phase_id, i));
336 }
337 buf.print_cr();
338 }
339
340 void G1GCPhasePrinter::print_count_values(LineBuffer& buf, G1GCPhaseTimes::GCPhases phase_id, WorkerDataArray<size_t>* sub_count) {
341 for (uint i = 0; i < sub_count->_length; ++i) {
342 buf.append(" " SIZE_FORMAT, _phase_times->get_sub_count(phase_id, i));
343 }
344 buf.print_cr();
345 }
346
347 void G1GCPhasePrinter::print_sub_count(G1GCPhaseTimes::GCPhases phase_id, WorkerDataArray<size_t>* sub_count) {
348 LineBuffer buf(sub_count->_indent_level);
349 buf.append("[%s:", sub_count->_title);
350
351 if (G1Log::finest()) {
352 print_count_values(buf, phase_id, sub_count);
353 }
354
355 assert(sub_count->_print_sum, err_msg("%s does not have print sum true even though it is a count", sub_count->_title));
356
357 buf.append_and_print_cr(" Min: " SIZE_FORMAT ", Avg: %.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT "]",
358 _phase_times->min_sub_count(phase_id), _phase_times->average_sub_count(phase_id), _phase_times->max_sub_count(phase_id),
359 _phase_times->max_sub_count(phase_id) - _phase_times->min_sub_count(phase_id), _phase_times->sum_sub_count(phase_id));
360 }
361
362 void G1GCPhasePrinter::print_multi_length(G1GCPhaseTimes::GCPhases phase_id, WorkerDataArray<double>* phase) {
363 LineBuffer buf(phase->_indent_level);
364 buf.append("[%s:", phase->_title);
365
366 if (G1Log::finest()) {
367 print_time_values(buf, phase_id, phase);
368 }
369
370 buf.append(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf",
371 _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
372 _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
373
374 if (phase->_print_sum) {
375 // for things like the start and end times the sum is not
376 // that relevant
377 buf.append(", Sum: %.1lf", _phase_times->sum_time_ms(phase_id));
378 }
379
380 buf.append_and_print_cr("]");
381
382 if (phase->_sub_count != NULL) {
383 print_sub_count(phase_id, phase->_sub_count);
384 }
385 }
386
387 void G1GCPhasePrinter::print(G1GCPhaseTimes::GCPhases phase_id) {
388 WorkerDataArray<double>* phase = _phase_times->_gc_phases[phase_id];
389
390 if (phase->_log_level > G1Log::level() || !phase->_enabled) {
391 return;
392 }
393
394 if (phase->_length == 1) {
395 print_single_length(phase_id, phase);
396 } else {
397 print_multi_length(phase_id, phase);
398 }
399 }
|