115
116 double worker_known_time =
117 _gc_par_phases[ExtRootScan]->get(i) +
118 _gc_par_phases[SATBFiltering]->get(i) +
119 _gc_par_phases[UpdateRS]->get(i) +
120 _gc_par_phases[ScanRS]->get(i) +
121 _gc_par_phases[CodeRoots]->get(i) +
122 _gc_par_phases[ObjCopy]->get(i) +
123 _gc_par_phases[Termination]->get(i);
124
125 record_time_secs(Other, i, worker_time - worker_known_time);
126 }
127
128 for (int i = 0; i < GCParPhasesSentinel; i++) {
129 if (_gc_par_phases[i] != NULL) {
130 _gc_par_phases[i]->verify(_active_gc_threads);
131 }
132 }
133 }
134
135 double G1GCPhaseTimes::info_line(const char* str, double value) {
136 log_info(gc, phases)("%s%s: %.1lfms", Indents[1], str, value);
137 return value;
138 }
139
140 void G1GCPhaseTimes::debug_line(const char* str, double value) {
141 log_debug(gc, phases)("%s%s: %.1lfms", Indents[2], str, value);
142 }
143
144 void G1GCPhaseTimes::trace_line(const char* str, double value) {
145 log_trace(gc, phases)("%s%s: %.1lfms", Indents[3], str, value);
146 }
147
148 void G1GCPhaseTimes::trace_line(const char* str, size_t value) {
149 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], str, value);
150 }
151
152 void G1GCPhaseTimes::trace_phase_tasks(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) {
153 LogHandle(gc, phases, task) log;
154 if (!log.is_trace()) {
155 return;
156 }
157 ResourceMark rm;
158 outputStream* out = log.trace_stream();
159 out->print("%s%-25s", indent, "");
160 for (uint i = 0; i < _active_gc_threads; ++i) {
161 out->print(" %4.1lf", get_time_ms(phase_id, i));
162 }
163 out->cr();
164 }
165
166 void G1GCPhaseTimes::trace_phase_counts(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) {
167 LogHandle(gc, phases, task) log;
168 if (!log.is_trace()) {
169 return;
170 }
171 ResourceMark rm;
172 outputStream* out = log.trace_stream();
173 out->print("%s%-25s", indent, "");
174 for (uint i = 0; i < _active_gc_threads; ++i) {
175 out->print(" " SIZE_FORMAT, get_thread_work_item(phase_id, i));
176 }
177 out->cr();
178 }
179
180 void G1GCPhaseTimes::debug_phase(G1GCPhaseTimes::GCParPhases phase_id) {
181 WorkerDataArray<double>* phase = _gc_par_phases[phase_id];
182 log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
183 Indents[2], phase->title(),
184 min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id),
185 max_time_ms(phase_id) - min_time_ms(phase_id), sum_time_ms(phase_id));
186 trace_phase_tasks(Indents[2], phase_id);
187 if (phase->thread_work_items() != NULL) {
188 log_debug(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT,
189 Indents[3], phase->thread_work_items()->title(),
190 min_thread_work_items(phase_id), average_thread_work_items(phase_id), max_thread_work_items(phase_id),
191 max_thread_work_items(phase_id) - min_thread_work_items(phase_id), sum_thread_work_items(phase_id));
192 trace_phase_counts(Indents[3], phase_id);
193 }
194 }
195
196 void G1GCPhaseTimes::trace_phase(G1GCPhaseTimes::GCParPhases phase_id) {
197 WorkerDataArray<double>* phase = _gc_par_phases[phase_id];
198 log_trace(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
199 Indents[3], phase->title(),
200 min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id),
201 max_time_ms(phase_id) - min_time_ms(phase_id), sum_time_ms(phase_id));
202 trace_phase_tasks(Indents[3], phase_id);
203 if (phase->thread_work_items() != NULL) {
204 log_trace(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT,
205 Indents[4], phase->thread_work_items()->title(),
206 min_thread_work_items(phase_id), average_thread_work_items(phase_id), max_thread_work_items(phase_id),
207 max_thread_work_items(phase_id) - min_thread_work_items(phase_id), sum_thread_work_items(phase_id));
208 trace_phase_counts(Indents[4], phase_id);
209 }
210 }
211
212 void G1GCPhaseTimes::trace_phase_no_sum(G1GCPhaseTimes::GCParPhases phase_id) {
213 WorkerDataArray<double>* phase = _gc_par_phases[phase_id];
214 log_trace(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf",
215 Indents[3], phase->title(),
216 min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id),
217 max_time_ms(phase_id) - min_time_ms(phase_id));
218 trace_phase_tasks(Indents[3], phase_id);
219 assert(phase->thread_work_items() == NULL, "work_items not implemented for no_sum.");
220 }
221
222 // record the time a phase took in seconds
223 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
224 _gc_par_phases[phase]->set(worker_i, secs);
225 }
226
227 // add a number of seconds to a phase
228 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
229 _gc_par_phases[phase]->add(worker_i, secs);
230 }
231
232 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) {
233 _gc_par_phases[phase]->set_thread_work_item(worker_i, count);
234 }
235
236 // return the average time for a phase in milliseconds
237 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
238 return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
239 }
240
241 double G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) {
242 return _gc_par_phases[phase]->get(worker_i) * 1000.0;
243 }
244
245 double G1GCPhaseTimes::sum_time_ms(GCParPhases phase) {
246 return _gc_par_phases[phase]->sum(_active_gc_threads) * 1000.0;
247 }
248
249 double G1GCPhaseTimes::min_time_ms(GCParPhases phase) {
250 return _gc_par_phases[phase]->minimum(_active_gc_threads) * 1000.0;
251 }
252
253 double G1GCPhaseTimes::max_time_ms(GCParPhases phase) {
254 return _gc_par_phases[phase]->maximum(_active_gc_threads) * 1000.0;
255 }
256
257 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i) {
258 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
259 return _gc_par_phases[phase]->thread_work_items()->get(worker_i);
260 }
261
262 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
263 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
264 return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
265 }
266
267 double G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) {
268 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
269 return _gc_par_phases[phase]->thread_work_items()->average(_active_gc_threads);
270 }
271
272 size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {
273 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
274 return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads);
275 }
276
277 size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {
278 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
279 return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads);
280 }
281
282 void G1GCPhaseTimes::print() {
283 note_gc_end();
284
285 double accounted_time_ms = _external_accounted_time_ms;
286 if (_root_region_scan_wait_time_ms > 0.0) {
287 accounted_time_ms += info_line("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
288 }
289
290 accounted_time_ms += info_line("Evacuate Collection Set", _cur_collection_par_time_ms);
291 trace_phase_no_sum(GCWorkerStart);
292 debug_phase(ExtRootScan);
293 for (int i = ThreadRoots; i <= SATBFiltering; i++) {
294 trace_phase((GCParPhases) i);
295 }
296 debug_phase(UpdateRS);
297 if (ConcurrentG1Refine::hot_card_cache_enabled()) {
298 trace_phase(ScanHCC);
299 }
300 debug_phase(ScanRS);
301 debug_phase(CodeRoots);
302 debug_phase(ObjCopy);
303 debug_phase(Termination);
304 debug_phase(Other);
305 debug_phase(GCWorkerTotal);
306 trace_phase_no_sum(GCWorkerEnd);
307
308 accounted_time_ms += info_line("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms);
309 debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
310 debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
311
312 if (G1StringDedup::is_enabled()) {
313 accounted_time_ms += info_line("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
314 debug_phase(StringDedupQueueFixup);
315 debug_phase(StringDedupTableFixup);
316 }
317 accounted_time_ms += info_line("Clear Card Table", _cur_clear_ct_time_ms);
318 accounted_time_ms += info_line("Expand Heap After Collection", _cur_expand_heap_time_ms);
319
320 double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms;
321 accounted_time_ms += info_line("Free Collection Set", free_cset_time);
322 debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms);
323 debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms);
324
325 info_line("Other", _gc_pause_time_ms - accounted_time_ms);
326 if (_cur_verify_before_time_ms > 0.0) {
327 debug_line("Verify Before", _cur_verify_before_time_ms);
328 }
329 if (G1CollectedHeap::heap()->evacuation_failed()) {
330 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
331 _cur_evac_fail_restore_remsets;
332 debug_line("Evacuation Failure", evac_fail_handling);
333 trace_line("Recalculate Used", _cur_evac_fail_recalc_used);
334 trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
335 trace_line("Restore RemSet", _cur_evac_fail_restore_remsets);
336 }
337 debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
338 debug_line("Ref Proc", _cur_ref_proc_time_ms);
339 debug_line("Ref Enq", _cur_ref_enq_time_ms);
340 debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
341 trace_phase(RedirtyCards);
342 if (G1EagerReclaimHumongousObjects) {
343 debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
344 trace_line("Humongous Total", _cur_fast_reclaim_humongous_total);
345 trace_line("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
346 debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
347 trace_line("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
348 }
349 if (_cur_verify_after_time_ms > 0.0) {
350 debug_line("Verify After", _cur_verify_after_time_ms);
351 }
352 }
353
354 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
355 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
356 if (_phase_times != NULL) {
357 _start_time = os::elapsedTime();
358 }
359 }
360
361 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
362 if (_phase_times != NULL) {
363 _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
364 }
365 }
366
|
115
116 double worker_known_time =
117 _gc_par_phases[ExtRootScan]->get(i) +
118 _gc_par_phases[SATBFiltering]->get(i) +
119 _gc_par_phases[UpdateRS]->get(i) +
120 _gc_par_phases[ScanRS]->get(i) +
121 _gc_par_phases[CodeRoots]->get(i) +
122 _gc_par_phases[ObjCopy]->get(i) +
123 _gc_par_phases[Termination]->get(i);
124
125 record_time_secs(Other, i, worker_time - worker_known_time);
126 }
127
128 for (int i = 0; i < GCParPhasesSentinel; i++) {
129 if (_gc_par_phases[i] != NULL) {
130 _gc_par_phases[i]->verify(_active_gc_threads);
131 }
132 }
133 }
134
135 // record the time a phase took in seconds
136 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
137 _gc_par_phases[phase]->set(worker_i, secs);
138 }
139
140 // add a number of seconds to a phase
141 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
142 _gc_par_phases[phase]->add(worker_i, secs);
143 }
144
145 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) {
146 _gc_par_phases[phase]->set_thread_work_item(worker_i, count);
147 }
148
149 // return the average time for a phase in milliseconds
150 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
151 return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
152 }
153
154 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
155 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
156 return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
157 }
158
159 template <class T>
160 void G1GCPhaseTimes::details(T* phase, const char* indent) {
161 LogHandle(gc, phases, task) log;
162 if (log.is_level(LogLevel::Trace)) {
163 outputStream* trace_out = log.trace_stream();
164 trace_out->print("%s", indent);
165 phase->print_details_on(trace_out, _active_gc_threads);
166 }
167 }
168
169 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
170 out->print("%s", Indents[indent]);
171 phase->print_summary_on(out, _active_gc_threads, print_sum);
172 details(phase, Indents[indent]);
173
174 WorkerDataArray<size_t>* work_items = phase->thread_work_items();
175 if (work_items != NULL) {
176 out->print("%s", Indents[indent + 1]);
177 work_items->print_summary_on(out, _active_gc_threads, true);
178 details(work_items, Indents[indent + 1]);
179 }
180 }
181
182 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
183 LogHandle(gc, phases) log;
184 if (log.is_level(LogLevel::Debug)) {
185 ResourceMark rm;
186 log_phase(phase, 2, log.debug_stream(), true);
187 }
188 }
189
190 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) {
191 LogHandle(gc, phases) log;
192 if (log.is_level(LogLevel::Trace)) {
193 ResourceMark rm;
194 log_phase(phase, 3, log.trace_stream(), print_sum);
195 }
196 }
197
198 #define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms"
199 #define PHASE_SIZE_FORMAT "%s%s: " SIZE_FORMAT
200
201 #define info_line(str, value) \
202 log_info(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[1], str, value);
203
204 #define debug_line(str, value) \
205 log_debug(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[2], str, value);
206
207 #define trace_line(str, value) \
208 log_trace(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[3], str, value);
209
210 #define trace_line_sz(str, value) \
211 log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);
212
213 #define trace_line_ms(str, value) \
214 log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);
215
216 #define info_line_and_account(str, value) \
217 info_line(str, value); \
218 accounted_time_ms += value;
219
220 void G1GCPhaseTimes::print() {
221 note_gc_end();
222
223 double accounted_time_ms = _external_accounted_time_ms;
224 if (_root_region_scan_wait_time_ms > 0.0) {
225 info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
226 }
227
228 info_line_and_account("Evacuate Collection Set", _cur_collection_par_time_ms);
229 trace_phase(_gc_par_phases[GCWorkerStart], false);
230 debug_phase(_gc_par_phases[ExtRootScan]);
231 for (int i = ThreadRoots; i <= SATBFiltering; i++) {
232 trace_phase(_gc_par_phases[i]);
233 }
234 debug_phase(_gc_par_phases[UpdateRS]);
235 if (ConcurrentG1Refine::hot_card_cache_enabled()) {
236 trace_phase(_gc_par_phases[ScanHCC]);
237 }
238 debug_phase(_gc_par_phases[ScanRS]);
239 debug_phase(_gc_par_phases[CodeRoots]);
240 debug_phase(_gc_par_phases[ObjCopy]);
241 debug_phase(_gc_par_phases[Termination]);
242 debug_phase(_gc_par_phases[Other]);
243 debug_phase(_gc_par_phases[GCWorkerTotal]);
244 trace_phase(_gc_par_phases[GCWorkerEnd], false);
245
246 info_line_and_account("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms);
247 debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
248 debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
249
250 if (G1StringDedup::is_enabled()) {
251 info_line_and_account("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
252 debug_phase(_gc_par_phases[StringDedupQueueFixup]);
253 debug_phase(_gc_par_phases[StringDedupTableFixup]);
254 }
255 info_line_and_account("Clear Card Table", _cur_clear_ct_time_ms);
256 info_line_and_account("Expand Heap After Collection", _cur_expand_heap_time_ms);
257
258 double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms;
259 info_line_and_account("Free Collection Set", free_cset_time);
260 debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms);
261 debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms);
262
263 info_line("Other", _gc_pause_time_ms - accounted_time_ms);
264 if (_cur_verify_before_time_ms > 0.0) {
265 debug_line("Verify Before", _cur_verify_before_time_ms);
266 }
267 if (G1CollectedHeap::heap()->evacuation_failed()) {
268 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
269 _cur_evac_fail_restore_remsets;
270 debug_line("Evacuation Failure", evac_fail_handling);
271 trace_line("Recalculate Used", _cur_evac_fail_recalc_used);
272 trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
273 trace_line("Restore RemSet", _cur_evac_fail_restore_remsets);
274 }
275 debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
276 debug_line("Ref Proc", _cur_ref_proc_time_ms);
277 debug_line("Ref Enq", _cur_ref_enq_time_ms);
278 debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
279 trace_phase(_gc_par_phases[RedirtyCards]);
280 if (G1EagerReclaimHumongousObjects) {
281 debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
282 trace_line_sz("Humongous Total", _cur_fast_reclaim_humongous_total);
283 trace_line_sz("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
284 debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
285 trace_line_sz("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
286 }
287 if (_cur_verify_after_time_ms > 0.0) {
288 debug_line("Verify After", _cur_verify_after_time_ms);
289 }
290 }
291
292 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
293 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
294 if (_phase_times != NULL) {
295 _start_time = os::elapsedTime();
296 }
297 }
298
299 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
300 if (_phase_times != NULL) {
301 _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
302 }
303 }
304
|