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