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