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