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