1 /*
2 * Copyright (c) 2013, 2019, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25 #include "precompiled.hpp"
26 #include "gc/g1/g1CollectedHeap.inline.hpp"
27 #include "gc/g1/g1GCPhaseTimes.hpp"
28 #include "gc/g1/g1HotCardCache.hpp"
29 #include "gc/g1/g1ParScanThreadState.inline.hpp"
30 #include "gc/g1/g1StringDedup.hpp"
31 #include "gc/shared/gcTimer.hpp"
32 #include "gc/shared/workerDataArray.inline.hpp"
33 #include "memory/resourceArea.hpp"
34 #include "logging/log.hpp"
35 #include "logging/logStream.hpp"
36 #include "runtime/timer.hpp"
37 #include "runtime/os.hpp"
38 #include "utilities/macros.hpp"
39
40 static const char* Indents[5] = {"", " ", " ", " ", " "};
41
42 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
43 _max_gc_threads(max_gc_threads),
44 _gc_start_counter(0),
45 _gc_pause_time_ms(0.0),
46 _ref_phase_times(gc_timer, max_gc_threads),
47 _weak_phase_times(max_gc_threads)
48 {
49 assert(max_gc_threads > 0, "Must have some GC threads");
50
51 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
52 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
53
54 // Root scanning phases
55 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
56 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
57 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
58 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
59 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
60 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
61 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
62 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
63 #if INCLUDE_AOT
64 _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scan (ms):");
65 #endif
66 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
67 _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
68 _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
69 _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
70
71 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
72 if (G1HotCardCache::default_use_cache()) {
73 _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
74 } else {
75 _gc_par_phases[ScanHCC] = NULL;
76 }
77 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
78 _gc_par_phases[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):");
79 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scan (ms):");
80 _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Optional Code Root Scan (ms):");
81 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
82 _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
83 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
84 _gc_par_phases[OptTermination] = new WorkerDataArray<double>(max_gc_threads, "Optional Termination (ms):");
85 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
86 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
87 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
88
89 _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
90 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
91 _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
92 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
93 _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
94 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
95
96 _opt_scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
97 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_scanned_cards, ScanRSScannedCards);
98 _opt_scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
99 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_claimed_cards, ScanRSClaimedCards);
100 _opt_scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
101 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_skipped_cards, ScanRSSkippedCards);
102 _opt_scan_rs_scanned_opt_refs = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Refs:");
103 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_scanned_opt_refs, ScanRSScannedOptRefs);
104 _opt_scan_rs_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
105 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_used_memory, ScanRSUsedMemory);
106
107 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
108 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
109 _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
110 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
111 _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
112 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
113
114 _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
115 _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
116 _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
117 _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
118
119 _opt_obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
120 _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
121 _opt_obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
122 _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
123
124 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
125 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
126
127 _opt_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Optional Termination Attempts:");
128 _gc_par_phases[OptTermination]->link_thread_work_items(_opt_termination_attempts);
129
130 if (UseStringDeduplication) {
131 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
132 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
133 } else {
134 _gc_par_phases[StringDedupQueueFixup] = NULL;
135 _gc_par_phases[StringDedupTableFixup] = NULL;
136 }
137
138 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
139 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
140 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
141
142 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
143 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
144
145 reset();
146 }
147
148 void G1GCPhaseTimes::reset() {
149 _cur_collection_initial_evac_time_ms = 0.0;
150 _cur_optional_evac_ms = 0.0;
151 _cur_collection_code_root_fixup_time_ms = 0.0;
152 _cur_strong_code_root_purge_time_ms = 0.0;
153 _cur_evac_fail_recalc_used = 0.0;
154 _cur_evac_fail_remove_self_forwards = 0.0;
155 _cur_string_deduplication_time_ms = 0.0;
156 _cur_prepare_tlab_time_ms = 0.0;
157 _cur_resize_tlab_time_ms = 0.0;
158 _cur_derived_pointer_table_update_time_ms = 0.0;
159 _cur_clear_ct_time_ms = 0.0;
160 _cur_expand_heap_time_ms = 0.0;
161 _cur_ref_proc_time_ms = 0.0;
162 _cur_collection_start_sec = 0.0;
163 _root_region_scan_wait_time_ms = 0.0;
164 _external_accounted_time_ms = 0.0;
165 _recorded_clear_claimed_marks_time_ms = 0.0;
166 _recorded_young_cset_choice_time_ms = 0.0;
167 _recorded_non_young_cset_choice_time_ms = 0.0;
168 _recorded_redirty_logged_cards_time_ms = 0.0;
169 _recorded_preserve_cm_referents_time_ms = 0.0;
170 _recorded_merge_pss_time_ms = 0.0;
171 _recorded_start_new_cset_time_ms = 0.0;
172 _recorded_total_free_cset_time_ms = 0.0;
173 _recorded_serial_free_cset_time_ms = 0.0;
174 _cur_fast_reclaim_humongous_time_ms = 0.0;
175 _cur_fast_reclaim_humongous_register_time_ms = 0.0;
176 _cur_fast_reclaim_humongous_total = 0;
177 _cur_fast_reclaim_humongous_candidates = 0;
178 _cur_fast_reclaim_humongous_reclaimed = 0;
179 _cur_verify_before_time_ms = 0.0;
180 _cur_verify_after_time_ms = 0.0;
181
182 for (int i = 0; i < GCParPhasesSentinel; i++) {
183 if (_gc_par_phases[i] != NULL) {
184 _gc_par_phases[i]->reset();
185 }
186 }
187
188 _ref_phase_times.reset();
189 _weak_phase_times.reset();
190 }
191
192 void G1GCPhaseTimes::note_gc_start() {
193 _gc_start_counter = os::elapsed_counter();
194 reset();
195 }
196
197 #define ASSERT_PHASE_UNINITIALIZED(phase) \
198 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
199
200 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
201 if (_gc_par_phases[phase] == NULL) {
202 return 0.0;
203 }
204 double value = _gc_par_phases[phase]->get(worker);
205 if (value != WorkerDataArray<double>::uninitialized()) {
206 return value;
207 }
208 return 0.0;
209 }
210
211 void G1GCPhaseTimes::note_gc_end() {
212 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
213
214 double uninitialized = WorkerDataArray<double>::uninitialized();
215
216 for (uint i = 0; i < _max_gc_threads; i++) {
217 double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
218 if (worker_start != uninitialized) {
219 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
220 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
221 record_time_secs(GCWorkerTotal, i , total_worker_time);
222
223 double worker_known_time = worker_time(ExtRootScan, i) +
224 worker_time(ScanHCC, i) +
225 worker_time(UpdateRS, i) +
226 worker_time(ScanRS, i) +
227 worker_time(CodeRoots, i) +
228 worker_time(ObjCopy, i) +
229 worker_time(Termination, i);
230
231 record_time_secs(Other, i, total_worker_time - worker_known_time);
232 } else {
233 // Make sure all slots are uninitialized since this thread did not seem to have been started
234 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
235 ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
236 ASSERT_PHASE_UNINITIALIZED(ScanHCC);
237 ASSERT_PHASE_UNINITIALIZED(UpdateRS);
238 ASSERT_PHASE_UNINITIALIZED(ScanRS);
239 ASSERT_PHASE_UNINITIALIZED(CodeRoots);
240 ASSERT_PHASE_UNINITIALIZED(ObjCopy);
241 ASSERT_PHASE_UNINITIALIZED(Termination);
242 }
243 }
244 }
245
246 #undef ASSERT_PHASE_UNINITIALIZED
247
248 // record the time a phase took in seconds
249 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
250 _gc_par_phases[phase]->set(worker_i, secs);
251 }
252
253 // add a number of seconds to a phase
254 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
255 _gc_par_phases[phase]->add(worker_i, secs);
256 }
257
258 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
259 if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
260 record_time_secs(phase, worker_i, secs);
261 } else {
262 add_time_secs(phase, worker_i, secs);
263 }
264 }
265
266 double G1GCPhaseTimes::get_time_secs(GCParPhases phase, uint worker_i) {
267 return _gc_par_phases[phase]->get(worker_i);
268 }
269
270 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
271 _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
272 }
273
274 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
275 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index);
276 }
277
278 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i, uint index) {
279 return _gc_par_phases[phase]->get_thread_work_item(worker_i, index);
280 }
281
282 // return the average time for a phase in milliseconds
283 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
284 return _gc_par_phases[phase]->average() * 1000.0;
285 }
286
287 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
288 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
289 return _gc_par_phases[phase]->thread_work_items(index)->sum();
290 }
291
292 template <class T>
293 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
294 LogTarget(Trace, gc, phases, task) lt;
295 if (lt.is_enabled()) {
296 LogStream ls(lt);
297 ls.print("%s", indent);
298 phase->print_details_on(&ls);
299 }
300 }
301
302 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
303 out->print("%s", Indents[indent]);
304 phase->print_summary_on(out, print_sum);
305 details(phase, Indents[indent]);
306
307 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
308 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
309 if (work_items != NULL) {
310 out->print("%s", Indents[indent + 1]);
311 work_items->print_summary_on(out, true);
312 details(work_items, Indents[indent + 1]);
313 }
314 }
315 }
316
317 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const {
318 LogTarget(Debug, gc, phases) lt;
319 if (lt.is_enabled()) {
320 ResourceMark rm;
321 LogStream ls(lt);
322 log_phase(phase, 2 + extra_indent, &ls, true);
323 }
324 }
325
326 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
327 LogTarget(Trace, gc, phases) lt;
328 if (lt.is_enabled()) {
329 LogStream ls(lt);
330 log_phase(phase, 3, &ls, print_sum);
331 }
332 }
333
334 #define TIME_FORMAT "%.1lfms"
335
336 void G1GCPhaseTimes::info_time(const char* name, double value) const {
337 log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
338 }
339
340 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
341 log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
342 }
343
344 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
345 LogTarget(Debug, gc, phases) lt;
346 LogTarget(Debug, gc, phases, ref) lt2;
347
348 if (lt.is_enabled()) {
349 LogStream ls(lt);
350 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
351 } else if (lt2.is_enabled()) {
352 LogStream ls(lt2);
353 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
354 }
355 }
356
357 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
358 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
359 }
360
361 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
362 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
363 }
364
365 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
366 const double sum_ms = _root_region_scan_wait_time_ms +
367 _recorded_young_cset_choice_time_ms +
368 _recorded_non_young_cset_choice_time_ms +
369 _cur_fast_reclaim_humongous_register_time_ms +
370 _recorded_clear_claimed_marks_time_ms;
371
372 info_time("Pre Evacuate Collection Set", sum_ms);
373
374 if (_root_region_scan_wait_time_ms > 0.0) {
375 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
376 }
377 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
378 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
379 if (G1EagerReclaimHumongousObjects) {
380 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
381 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
382 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
383 }
384
385 if (_recorded_clear_claimed_marks_time_ms > 0.0) {
386 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
387 }
388 return sum_ms;
389 }
390
391 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
392 const double sum_ms = _cur_optional_evac_ms;
393 if (sum_ms > 0) {
394 info_time("Evacuate Optional Collection Set", sum_ms);
395 debug_phase(_gc_par_phases[OptScanRS]);
396 debug_phase(_gc_par_phases[OptObjCopy]);
397 debug_phase(_gc_par_phases[OptCodeRoots]);
398 debug_phase(_gc_par_phases[OptTermination]);
399 }
400 return sum_ms;
401 }
402
403 double G1GCPhaseTimes::print_evacuate_collection_set() const {
404 const double sum_ms = _cur_collection_initial_evac_time_ms;
405
406 info_time("Evacuate Collection Set", sum_ms);
407
408 trace_phase(_gc_par_phases[GCWorkerStart], false);
409 debug_phase(_gc_par_phases[ExtRootScan]);
410 for (int i = ExtRootScanSubPhasesStart; i <= ExtRootScanSubPhasesEnd; i++) {
411 trace_phase(_gc_par_phases[i]);
412 }
413 if (G1HotCardCache::default_use_cache()) {
414 debug_phase(_gc_par_phases[ScanHCC]);
415 }
416 debug_phase(_gc_par_phases[UpdateRS]);
417 debug_phase(_gc_par_phases[ScanRS]);
418 debug_phase(_gc_par_phases[CodeRoots]);
419 debug_phase(_gc_par_phases[ObjCopy]);
420 debug_phase(_gc_par_phases[Termination]);
421 debug_phase(_gc_par_phases[Other]);
422 debug_phase(_gc_par_phases[GCWorkerTotal]);
423 trace_phase(_gc_par_phases[GCWorkerEnd], false);
424
425 return sum_ms;
426 }
427
428 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
429 const double evac_fail_handling = _cur_evac_fail_recalc_used +
430 _cur_evac_fail_remove_self_forwards;
431 const double sum_ms = evac_fail_handling +
432 _cur_collection_code_root_fixup_time_ms +
433 _recorded_preserve_cm_referents_time_ms +
434 _cur_ref_proc_time_ms +
435 (_weak_phase_times.total_time_sec() * MILLIUNITS) +
436 _cur_clear_ct_time_ms +
437 _recorded_merge_pss_time_ms +
438 _cur_strong_code_root_purge_time_ms +
439 _recorded_redirty_logged_cards_time_ms +
440 _recorded_total_free_cset_time_ms +
441 _cur_fast_reclaim_humongous_time_ms +
442 _cur_expand_heap_time_ms +
443 _cur_string_deduplication_time_ms;
444
445 info_time("Post Evacuate Collection Set", sum_ms);
446
447 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
448
449 debug_time("Clear Card Table", _cur_clear_ct_time_ms);
450
451 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
452 _ref_phase_times.print_all_references(2, false);
453 _weak_phase_times.log_print(2);
454
455 if (G1StringDedup::is_enabled()) {
456 debug_time("String Deduplication", _cur_string_deduplication_time_ms);
457 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1);
458 debug_phase(_gc_par_phases[StringDedupTableFixup], 1);
459 }
460
461 if (G1CollectedHeap::heap()->evacuation_failed()) {
462 debug_time("Evacuation Failure", evac_fail_handling);
463 trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
464 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
465 }
466
467 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
468 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
469
470 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
471 trace_phase(_gc_par_phases[RedirtyCards]);
472 #if COMPILER2_OR_JVMCI
473 debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
474 #endif
475
476 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
477 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
478 trace_phase(_gc_par_phases[YoungFreeCSet]);
479 trace_phase(_gc_par_phases[NonYoungFreeCSet]);
480
481 if (G1EagerReclaimHumongousObjects) {
482 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
483 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
484 }
485 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
486 if (UseTLAB && ResizeTLAB) {
487 debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
488 }
489 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
490
491
492 return sum_ms;
493 }
494
495 void G1GCPhaseTimes::print_other(double accounted_ms) const {
496 info_time("Other", _gc_pause_time_ms - accounted_ms);
497 }
498
499 void G1GCPhaseTimes::print() {
500 note_gc_end();
501
502 if (_cur_verify_before_time_ms > 0.0) {
503 debug_time("Verify Before", _cur_verify_before_time_ms);
504 }
505
506 double accounted_ms = 0.0;
507 accounted_ms += print_pre_evacuate_collection_set();
508 accounted_ms += print_evacuate_collection_set();
509 accounted_ms += print_evacuate_optional_collection_set();
510 accounted_ms += print_post_evacuate_collection_set();
511 print_other(accounted_ms);
512
513 if (_cur_verify_after_time_ms > 0.0) {
514 debug_time("Verify After", _cur_verify_after_time_ms);
515 }
516 }
517
518 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
519 static const char* names[] = {
520 "GCWorkerStart",
521 "ExtRootScan",
522 "ThreadRoots",
523 "UniverseRoots",
524 "JNIRoots",
525 "ObjectSynchronizerRoots",
526 "ManagementRoots",
527 "SystemDictionaryRoots",
528 "CLDGRoots",
529 "JVMTIRoots",
530 #if INCLUDE_AOT
531 "AOTCodeRoots",
532 #endif
533 "CMRefRoots",
534 "WaitForStrongCLD",
535 "WeakCLDRoots",
536 "SATBFiltering",
537 "UpdateRS",
538 "ScanHCC",
539 "ScanRS",
540 "OptScanRS",
541 "CodeRoots",
542 "OptCodeRoots",
543 "ObjCopy",
544 "OptObjCopy",
545 "Termination",
546 "OptTermination",
547 "Other",
548 "GCWorkerTotal",
549 "GCWorkerEnd",
550 "StringDedupQueueFixup",
551 "StringDedupTableFixup",
552 "RedirtyCards",
553 "YoungFreeCSet",
554 "NonYoungFreeCSet"
555 //GCParPhasesSentinel only used to tell end of enum
556 };
557
558 STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
559
560 return names[phase];
561 }
562
563 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
564 _pss(pss),
565 _start(Ticks::now()),
566 _total_time(total_time),
567 _trim_time(trim_time),
568 _stopped(false) {
569
570 assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
571 }
572
573 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
574 if (!_stopped) {
575 stop();
576 }
577 }
578
579 void G1EvacPhaseWithTrimTimeTracker::stop() {
580 assert(!_stopped, "Should only be called once");
581 _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
582 _trim_time += _pss->trim_ticks();
583 _pss->reset_trim_ticks();
584 _stopped = true;
585 }
586
587 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
588 _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() {
589 if (_phase_times != NULL) {
590 _start_time = Ticks::now();
591 }
592 }
593
594 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
595 if (_phase_times != NULL) {
596 _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
597 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
598 }
599 }
600
601 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
602 G1ParScanThreadState* pss,
603 G1GCPhaseTimes::GCParPhases phase,
604 uint worker_id) :
605 G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
606 _total_time(),
607 _trim_time(),
608 _trim_tracker(pss, _total_time, _trim_time) {
609 }
610
611 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
612 if (_phase_times != NULL) {
613 // Explicitly stop the trim tracker since it's not yet destructed.
614 _trim_tracker.stop();
615 // Exclude trim time by increasing the start time.
616 _start_time += _trim_time;
617 _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds());
618 }
619 }
620