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