153 }
154
155 #endif
156
157 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
158 _max_gc_threads(max_gc_threads),
159 _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
160 _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
161 _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
162 _last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
163 _last_update_rs_processed_buffers(_max_gc_threads, "%d"),
164 _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
165 _last_strong_code_root_scan_times_ms(_max_gc_threads, "%.1lf"),
166 _last_strong_code_root_mark_times_ms(_max_gc_threads, "%.1lf"),
167 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
168 _last_termination_times_ms(_max_gc_threads, "%.1lf"),
169 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
170 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
171 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
172 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"),
173 _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"),
174 _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf")
175 {
176 assert(max_gc_threads > 0, "Must have some GC threads");
177 }
178
179 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
180 assert(active_gc_threads > 0, "The number of threads must be > 0");
181 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
182 _active_gc_threads = active_gc_threads;
183
184 _last_gc_worker_start_times_ms.reset();
185 _last_ext_root_scan_times_ms.reset();
186 _last_satb_filtering_times_ms.reset();
187 _last_update_rs_times_ms.reset();
188 _last_update_rs_processed_buffers.reset();
189 _last_scan_rs_times_ms.reset();
190 _last_strong_code_root_scan_times_ms.reset();
191 _last_strong_code_root_mark_times_ms.reset();
192 _last_obj_copy_times_ms.reset();
193 _last_termination_times_ms.reset();
194 _last_termination_attempts.reset();
195 _last_gc_worker_end_times_ms.reset();
196 _last_gc_worker_times_ms.reset();
197 _last_gc_worker_other_times_ms.reset();
198 }
199
200 void G1GCPhaseTimes::note_gc_end() {
201 _last_gc_worker_start_times_ms.verify();
202 _last_ext_root_scan_times_ms.verify();
203 _last_satb_filtering_times_ms.verify();
204 _last_update_rs_times_ms.verify();
205 _last_update_rs_processed_buffers.verify();
206 _last_scan_rs_times_ms.verify();
207 _last_strong_code_root_scan_times_ms.verify();
208 _last_strong_code_root_mark_times_ms.verify();
209 _last_obj_copy_times_ms.verify();
210 _last_termination_times_ms.verify();
211 _last_termination_attempts.verify();
212 _last_gc_worker_end_times_ms.verify();
213
214 for (uint i = 0; i < _active_gc_threads; i++) {
215 double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i);
216 _last_gc_worker_times_ms.set(i, worker_time);
217
218 double worker_known_time = _last_ext_root_scan_times_ms.get(i) +
219 _last_satb_filtering_times_ms.get(i) +
220 _last_update_rs_times_ms.get(i) +
221 _last_scan_rs_times_ms.get(i) +
222 _last_strong_code_root_scan_times_ms.get(i) +
223 _last_strong_code_root_mark_times_ms.get(i) +
224 _last_obj_copy_times_ms.get(i) +
225 _last_termination_times_ms.get(i);
226
227 double worker_other_time = worker_time - worker_known_time;
228 _last_gc_worker_other_times_ms.set(i, worker_other_time);
229 }
230
231 _last_gc_worker_times_ms.verify();
232 _last_gc_worker_other_times_ms.verify();
233 }
234
235 void G1GCPhaseTimes::note_string_dedup_fixup_start() {
236 _cur_string_dedup_queue_fixup_worker_times_ms.reset();
237 _cur_string_dedup_table_fixup_worker_times_ms.reset();
238 }
239
240 void G1GCPhaseTimes::note_string_dedup_fixup_end() {
241 _cur_string_dedup_queue_fixup_worker_times_ms.verify();
242 _cur_string_dedup_table_fixup_worker_times_ms.verify();
243 }
244
245 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
246 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
247 }
248
249 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
250 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
251 }
252
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 if (G1DeferredRSUpdate) {
351 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
352 }
353 print_stats(2, "Free CSet",
354 (_recorded_young_free_cset_time_ms +
355 _recorded_non_young_free_cset_time_ms));
356 if (G1Log::finest()) {
357 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
358 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
359 }
360 if (_cur_verify_after_time_ms > 0.0) {
361 print_stats(2, "Verify After", _cur_verify_after_time_ms);
362 }
363 }
|
153 }
154
155 #endif
156
157 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
158 _max_gc_threads(max_gc_threads),
159 _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
160 _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
161 _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
162 _last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
163 _last_update_rs_processed_buffers(_max_gc_threads, "%d"),
164 _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
165 _last_strong_code_root_scan_times_ms(_max_gc_threads, "%.1lf"),
166 _last_strong_code_root_mark_times_ms(_max_gc_threads, "%.1lf"),
167 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
168 _last_termination_times_ms(_max_gc_threads, "%.1lf"),
169 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
170 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
171 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
172 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"),
173 _last_redirty_logged_cards_time_ms(_max_gc_threads, "%.1lf"),
174 _last_redirty_logged_cards_processed_cards(_max_gc_threads, SIZE_FORMAT),
175 _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"),
176 _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf")
177 {
178 assert(max_gc_threads > 0, "Must have some GC threads");
179 }
180
181 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
182 assert(active_gc_threads > 0, "The number of threads must be > 0");
183 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
184 _active_gc_threads = active_gc_threads;
185
186 _last_gc_worker_start_times_ms.reset();
187 _last_ext_root_scan_times_ms.reset();
188 _last_satb_filtering_times_ms.reset();
189 _last_update_rs_times_ms.reset();
190 _last_update_rs_processed_buffers.reset();
191 _last_scan_rs_times_ms.reset();
192 _last_strong_code_root_scan_times_ms.reset();
193 _last_strong_code_root_mark_times_ms.reset();
194 _last_obj_copy_times_ms.reset();
195 _last_termination_times_ms.reset();
196 _last_termination_attempts.reset();
197 _last_gc_worker_end_times_ms.reset();
198 _last_gc_worker_times_ms.reset();
199 _last_gc_worker_other_times_ms.reset();
200
201 _last_redirty_logged_cards_time_ms.reset();
202 _last_redirty_logged_cards_processed_cards.reset();
203
204 }
205
206 void G1GCPhaseTimes::note_gc_end() {
207 _last_gc_worker_start_times_ms.verify();
208 _last_ext_root_scan_times_ms.verify();
209 _last_satb_filtering_times_ms.verify();
210 _last_update_rs_times_ms.verify();
211 _last_update_rs_processed_buffers.verify();
212 _last_scan_rs_times_ms.verify();
213 _last_strong_code_root_scan_times_ms.verify();
214 _last_strong_code_root_mark_times_ms.verify();
215 _last_obj_copy_times_ms.verify();
216 _last_termination_times_ms.verify();
217 _last_termination_attempts.verify();
218 _last_gc_worker_end_times_ms.verify();
219
220 for (uint i = 0; i < _active_gc_threads; i++) {
221 double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i);
222 _last_gc_worker_times_ms.set(i, worker_time);
223
224 double worker_known_time = _last_ext_root_scan_times_ms.get(i) +
225 _last_satb_filtering_times_ms.get(i) +
226 _last_update_rs_times_ms.get(i) +
227 _last_scan_rs_times_ms.get(i) +
228 _last_strong_code_root_scan_times_ms.get(i) +
229 _last_strong_code_root_mark_times_ms.get(i) +
230 _last_obj_copy_times_ms.get(i) +
231 _last_termination_times_ms.get(i);
232
233 double worker_other_time = worker_time - worker_known_time;
234 _last_gc_worker_other_times_ms.set(i, worker_other_time);
235 }
236
237 _last_gc_worker_times_ms.verify();
238 _last_gc_worker_other_times_ms.verify();
239
240 _last_redirty_logged_cards_time_ms.verify();
241 _last_redirty_logged_cards_processed_cards.verify();
242 }
243
244 void G1GCPhaseTimes::note_string_dedup_fixup_start() {
245 _cur_string_dedup_queue_fixup_worker_times_ms.reset();
246 _cur_string_dedup_table_fixup_worker_times_ms.reset();
247 }
248
249 void G1GCPhaseTimes::note_string_dedup_fixup_end() {
250 _cur_string_dedup_queue_fixup_worker_times_ms.verify();
251 _cur_string_dedup_table_fixup_worker_times_ms.verify();
252 }
253
254 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
255 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
256 }
257
258 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
259 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
260 }
261
341 if (_cur_verify_before_time_ms > 0.0) {
342 print_stats(2, "Verify Before", _cur_verify_before_time_ms);
343 }
344 if (G1CollectedHeap::heap()->evacuation_failed()) {
345 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
346 _cur_evac_fail_restore_remsets;
347 print_stats(2, "Evacuation Failure", evac_fail_handling);
348 if (G1Log::finest()) {
349 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
350 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
351 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
352 }
353 }
354 print_stats(2, "Choose CSet",
355 (_recorded_young_cset_choice_time_ms +
356 _recorded_non_young_cset_choice_time_ms));
357 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
358 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
359 if (G1DeferredRSUpdate) {
360 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
361 if (G1Log::finest()) {
362 _last_redirty_logged_cards_time_ms.print(3, "Parallel Redirty");
363 _last_redirty_logged_cards_processed_cards.print(3, "Redirtied Cards");
364 }
365 }
366 print_stats(2, "Free CSet",
367 (_recorded_young_free_cset_time_ms +
368 _recorded_non_young_free_cset_time_ms));
369 if (G1Log::finest()) {
370 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
371 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
372 }
373 if (_cur_verify_after_time_ms > 0.0) {
374 print_stats(2, "Verify After", _cur_verify_after_time_ms);
375 }
376 }
|