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