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