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