8196341: Add JFR events for parallel phases of G1

0 /*
1  * Copyright (c) 2013, 2018, Oracle and/or its affiliates. All rights reserved.
2  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
3  *
4  * This code is free software; you can redistribute it and/or modify it
5  * under the terms of the GNU General Public License version 2 only, as
6  * published by the Free Software Foundation.
7  *
8  * This code is distributed in the hope that it will be useful, but WITHOUT
9  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
10  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
11  * version 2 for more details (a copy is included in the LICENSE file that
12  * accompanied this code).
13  *
14  * You should have received a copy of the GNU General Public License version
15  * 2 along with this work; if not, write to the Free Software Foundation,
16  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
17  *
18  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
19  * or visit www.oracle.com if you need additional information or have any
20  * questions.
21  *
22  */
23 
24 #include "precompiled.hpp"
25 #include "gc/g1/g1CollectedHeap.inline.hpp"
26 #include "gc/g1/g1GCPhaseTimes.hpp"
27 #include "gc/g1/g1HotCardCache.hpp"
28 #include "gc/g1/g1ParScanThreadState.inline.hpp"
29 #include "gc/g1/g1StringDedup.hpp"
30 #include "gc/shared/gcTimer.hpp"
31 #include "gc/shared/workerDataArray.inline.hpp"
32 #include "memory/resourceArea.hpp"
33 #include "logging/log.hpp"
34 #include "logging/logStream.hpp"
35 #include "runtime/timer.hpp"
36 #include "runtime/os.hpp"
37 #include "utilities/macros.hpp"
38 
39 static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
40 
41 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
42   _max_gc_threads(max_gc_threads),
43   _gc_start_counter(0),
44   _gc_pause_time_ms(0.0),
45   _ref_phase_times(gc_timer, max_gc_threads),
46   _weak_phase_times(max_gc_threads)
47 {
48   assert(max_gc_threads > 0, "Must have some GC threads");
49 
50   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
51   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
52 
53   // Root scanning phases
54   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
55   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable 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[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
76 #if INCLUDE_AOT
77   _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
78 #endif
79   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
80   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
81   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
82   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
83   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
84 
85   _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
86   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
87   _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
88   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
89   _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
90   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
91 
92   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
93   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
94   _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
95   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
96   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
97   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, ScanRSSkippedCards);
98 
99   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
100   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
101 
102   if (UseStringDeduplication) {
103     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
104     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
105   } else {
106     _gc_par_phases[StringDedupQueueFixup] = NULL;
107     _gc_par_phases[StringDedupTableFixup] = NULL;
108   }
109 
110   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
111   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
112   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
113 
114   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
115   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
116 
117   reset();
118 }
119 
120 void G1GCPhaseTimes::reset() {
121   _cur_collection_par_time_ms = 0.0;
122   _cur_collection_code_root_fixup_time_ms = 0.0;
123   _cur_strong_code_root_purge_time_ms = 0.0;
124   _cur_evac_fail_recalc_used = 0.0;
125   _cur_evac_fail_remove_self_forwards = 0.0;
126   _cur_string_dedup_fixup_time_ms = 0.0;
127   _cur_prepare_tlab_time_ms = 0.0;
128   _cur_resize_tlab_time_ms = 0.0;
129   _cur_derived_pointer_table_update_time_ms = 0.0;
130   _cur_clear_ct_time_ms = 0.0;
131   _cur_expand_heap_time_ms = 0.0;
132   _cur_ref_proc_time_ms = 0.0;
133   _cur_collection_start_sec = 0.0;
134   _root_region_scan_wait_time_ms = 0.0;
135   _external_accounted_time_ms = 0.0;
136   _recorded_clear_claimed_marks_time_ms = 0.0;
137   _recorded_young_cset_choice_time_ms = 0.0;
138   _recorded_non_young_cset_choice_time_ms = 0.0;
139   _recorded_redirty_logged_cards_time_ms = 0.0;
140   _recorded_preserve_cm_referents_time_ms = 0.0;
141   _recorded_merge_pss_time_ms = 0.0;
142   _recorded_start_new_cset_time_ms = 0.0;
143   _recorded_total_free_cset_time_ms = 0.0;
144   _recorded_serial_free_cset_time_ms = 0.0;
145   _cur_fast_reclaim_humongous_time_ms = 0.0;
146   _cur_fast_reclaim_humongous_register_time_ms = 0.0;
147   _cur_fast_reclaim_humongous_total = 0;
148   _cur_fast_reclaim_humongous_candidates = 0;
149   _cur_fast_reclaim_humongous_reclaimed = 0;
150   _cur_verify_before_time_ms = 0.0;
151   _cur_verify_after_time_ms = 0.0;
152 
153   for (int i = 0; i < GCParPhasesSentinel; i++) {
154     if (_gc_par_phases[i] != NULL) {
155       _gc_par_phases[i]->reset();
156     }
157   }
158 
159   _ref_phase_times.reset();
160   _weak_phase_times.reset();
161 }
162 
163 void G1GCPhaseTimes::note_gc_start() {
164   _gc_start_counter = os::elapsed_counter();
165   reset();
166 }
167 
168 #define ASSERT_PHASE_UNINITIALIZED(phase) \
169     assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for 
170 
171 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
172   if (_gc_par_phases[phase] == NULL) {
173     return 0.0;
174   }
175   double value = _gc_par_phases[phase]->get(worker);
176   if (value != WorkerDataArray<double>::uninitialized()) {
177     return value;
178   }
179   return 0.0;
180 }
181 
182 void G1GCPhaseTimes::note_gc_end() {
183   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
184 
185   double uninitialized = WorkerDataArray<double>::uninitialized();
186 
187   for (uint i = 0; i < _max_gc_threads; i++) {
188     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
189     if (worker_start != uninitialized) {
190       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
191       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
192       record_time_secs(GCWorkerTotal, i , total_worker_time);
193 
194       double worker_known_time = worker_time(ExtRootScan, i) +
195                                  worker_time(ScanHCC, i) +
196                                  worker_time(UpdateRS, i) +
197                                  worker_time(ScanRS, i) +
198                                  worker_time(CodeRoots, i) +
199                                  worker_time(ObjCopy, i) +
200                                  worker_time(Termination, i);
201 
202       record_time_secs(Other, i, total_worker_time - worker_known_time);
203     } else {
204       // Make sure all slots are uninitialized since this thread did not seem to have been started
205       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
206       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
207       ASSERT_PHASE_UNINITIALIZED(ScanHCC);
208       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
209       ASSERT_PHASE_UNINITIALIZED(ScanRS);
210       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
211       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
212       ASSERT_PHASE_UNINITIALIZED(Termination);
213     }
214   }
215 }
216 
217 #undef ASSERT_PHASE_UNINITIALIZED
218 
219 // record the time a phase took in seconds
220 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
221   _gc_par_phases[phase]->set(worker_i, secs);
222 }
223 
224 // add a number of seconds to a phase
225 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
226   _gc_par_phases[phase]->add(worker_i, secs);
227 }
228 
229 void G1GCPhaseTimes::record_or_add_objcopy_time_secs(uint worker_i, double secs) {
230   if (_gc_par_phases[ObjCopy]->get(worker_i) == _gc_par_phases[ObjCopy]->uninitialized()) {
231     record_time_secs(ObjCopy, worker_i, secs);
232   } else {
233     add_time_secs(ObjCopy, worker_i, secs);
234   }
235 }
236 
237 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
238   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
239 }
240 
241 // return the average time for a phase in milliseconds
242 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
243   return _gc_par_phases[phase]->average() * 1000.0;
244 }
245 
246 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
247   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
248   return _gc_par_phases[phase]->thread_work_items(index)->sum();
249 }
250 
251 template <class T>
252 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
253   LogTarget(Trace, gc, phases, task) lt;
254   if (lt.is_enabled()) {
255     LogStream ls(lt);
256     ls.print("%s", indent);
257     phase->print_details_on(&ls);
258   }
259 }
260 
261 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
262   out->print("%s", Indents[indent]);
263   phase->print_summary_on(out, print_sum);
264   details(phase, Indents[indent]);
265 
266   for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
267     WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
268     if (work_items != NULL) {
269       out->print("%s", Indents[indent + 1]);
270       work_items->print_summary_on(out, true);
271       details(work_items, Indents[indent + 1]);
272     }
273   }
274 }
275 
276 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) const {
277   LogTarget(Debug, gc, phases) lt;
278   if (lt.is_enabled()) {
279     ResourceMark rm;
280     LogStream ls(lt);
281     log_phase(phase, 2, &ls, true);
282   }
283 }
284 
285 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
286   LogTarget(Trace, gc, phases) lt;
287   if (lt.is_enabled()) {
288     LogStream ls(lt);
289     log_phase(phase, 3, &ls, print_sum);
290   }
291 }
292 
293 #define TIME_FORMAT "%.1lfms"
294 
295 void G1GCPhaseTimes::info_time(const char* name, double value) const {
296   log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
297 }
298 
299 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
300   log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
301 }
302 
303 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
304   LogTarget(Debug, gc, phases) lt;
305   LogTarget(Debug, gc, phases, ref) lt2;
306 
307   if (lt.is_enabled()) {
308     LogStream ls(lt);
309     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
310   } else if (lt2.is_enabled()) {
311     LogStream ls(lt2);
312     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
313   }
314 }
315 
316 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
317   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
318 }
319 
320 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
321   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
322 }
323 
324 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
325   const double sum_ms = _root_region_scan_wait_time_ms +
326                         _recorded_young_cset_choice_time_ms +
327                         _recorded_non_young_cset_choice_time_ms +
328                         _cur_fast_reclaim_humongous_register_time_ms +
329                         _recorded_clear_claimed_marks_time_ms;
330 
331   info_time("Pre Evacuate Collection Set", sum_ms);
332 
333   if (_root_region_scan_wait_time_ms > 0.0) {
334     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
335   }
336   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
337   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
338   if (G1EagerReclaimHumongousObjects) {
339     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
340     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
341     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
342   }
343 
344   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
345     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
346   }
347   return sum_ms;
348 }
349 
350 double G1GCPhaseTimes::print_evacuate_collection_set() const {
351   const double sum_ms = _cur_collection_par_time_ms;
352 
353   info_time("Evacuate Collection Set", sum_ms);
354 
355   trace_phase(_gc_par_phases[GCWorkerStart], false);
356   debug_phase(_gc_par_phases[ExtRootScan]);
357   for (int i = ThreadRoots; i <= SATBFiltering; i++) {
358     trace_phase(_gc_par_phases[i]);
359   }
360   debug_phase(_gc_par_phases[UpdateRS]);
361   if (G1HotCardCache::default_use_cache()) {
362     trace_phase(_gc_par_phases[ScanHCC]);
363   }
364   debug_phase(_gc_par_phases[ScanRS]);
365   debug_phase(_gc_par_phases[CodeRoots]);
366 #if INCLUDE_AOT
367   debug_phase(_gc_par_phases[AOTCodeRoots]);
368 #endif
369   debug_phase(_gc_par_phases[ObjCopy]);
370   debug_phase(_gc_par_phases[Termination]);
371   debug_phase(_gc_par_phases[Other]);
372   debug_phase(_gc_par_phases[GCWorkerTotal]);
373   trace_phase(_gc_par_phases[GCWorkerEnd], false);
374 
375   return sum_ms;
376 }
377 
378 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
379   const double evac_fail_handling = _cur_evac_fail_recalc_used +
380                                     _cur_evac_fail_remove_self_forwards;
381   const double sum_ms = evac_fail_handling +
382                         _cur_collection_code_root_fixup_time_ms +
383                         _recorded_preserve_cm_referents_time_ms +
384                         _cur_ref_proc_time_ms +
385                         (_weak_phase_times.total_time_sec() * MILLIUNITS) +
386                         _cur_clear_ct_time_ms +
387                         _recorded_merge_pss_time_ms +
388                         _cur_strong_code_root_purge_time_ms +
389                         _recorded_redirty_logged_cards_time_ms +
390                         _recorded_total_free_cset_time_ms +
391                         _cur_fast_reclaim_humongous_time_ms +
392                         _cur_expand_heap_time_ms +
393                         _cur_string_dedup_fixup_time_ms;
394 
395   info_time("Post Evacuate Collection Set", sum_ms);
396 
397   debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
398 
399   debug_time("Clear Card Table", _cur_clear_ct_time_ms);
400 
401   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
402   _ref_phase_times.print_all_references(2, false);
403   _weak_phase_times.log_print(2);
404 
405   if (G1StringDedup::is_enabled()) {
406     debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
407     debug_phase(_gc_par_phases[StringDedupQueueFixup]);
408     debug_phase(_gc_par_phases[StringDedupTableFixup]);
409   }
410 
411   if (G1CollectedHeap::heap()->evacuation_failed()) {
412     debug_time("Evacuation Failure", evac_fail_handling);
413     trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
414     trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
415   }
416 
417   debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
418   debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
419 
420   debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
421   trace_phase(_gc_par_phases[RedirtyCards]);
422 #if COMPILER2_OR_JVMCI
423   debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
424 #endif
425 
426   debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
427   trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
428   trace_phase(_gc_par_phases[YoungFreeCSet]);
429   trace_phase(_gc_par_phases[NonYoungFreeCSet]);
430 
431   if (G1EagerReclaimHumongousObjects) {
432     debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
433     trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
434   }
435   debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
436   if (UseTLAB && ResizeTLAB) {
437     debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
438   }
439   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
440 
441 
442   return sum_ms;
443 }
444 
445 void G1GCPhaseTimes::print_other(double accounted_ms) const {
446   info_time("Other", _gc_pause_time_ms - accounted_ms);
447 }
448 
449 void G1GCPhaseTimes::print() {
450   note_gc_end();
451 
452   if (_cur_verify_before_time_ms > 0.0) {
453     debug_time("Verify Before", _cur_verify_before_time_ms);
454   }
455 
456   double accounted_ms = 0.0;
457   accounted_ms += print_pre_evacuate_collection_set();
458   accounted_ms += print_evacuate_collection_set();
459   accounted_ms += print_post_evacuate_collection_set();
460   print_other(accounted_ms);
461 
462   if (_cur_verify_after_time_ms > 0.0) {
463     debug_time("Verify After", _cur_verify_after_time_ms);
464   }
465 }
466 
467 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
468   static const char* names[] = {
469       "GCWorkerStart",
470       "ExtRootScan",
471       "ThreadRoots",
472       "StringTableRoots",
473       "UniverseRoots",
474       "JNIRoots",
475       "ObjectSynchronizerRoots",
476       "ManagementRoots",
477       "SystemDictionaryRoots",
478       "CLDGRoots",
479       "JVMTIRoots",
480       "CMRefRoots",
481       "WaitForStrongCLD",
482       "WeakCLDRoots",
483       "SATBFiltering",
484       "UpdateRS",
485       "ScanHCC",
486       "ScanRS",
487       "CodeRoots",
488 #if INCLUDE_AOT
489       "AOTCodeRoots",
490 #endif
491       "ObjCopy",
492       "Termination",
493       "Other",
494       "GCWorkerTotal",
495       "GCWorkerEnd",
496       "StringDedupQueueFixup",
497       "StringDedupTableFixup",
498       "RedirtyCards",
499       "YoungFreeCSet",
500       "NonYoungFreeCSet"
501       //GCParPhasesSentinel only used to tell end of enum
502       };
503 
504   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string arr
505 
506   return names[phase];
507 }
508 
509 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& t
510   _pss(pss),
511   _start(Ticks::now()),
512   _total_time(total_time),
513   _trim_time(trim_time),
514   _stopped(false) {
515 
516   assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
517 }
518 
519 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
520   if (!_stopped) {
521     stop();
522   }
523 }
524 
525 void G1EvacPhaseWithTrimTimeTracker::stop() {
526   assert(!_stopped, "Should only be called once");
527   _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
528   _trim_time += _pss->trim_ticks();
529   _pss->reset_trim_ticks();
530   _stopped = true;
531 }
532 
533 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint wor
534   _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() {
535   if (_phase_times != NULL) {
536     _start_time = Ticks::now();
537   }
538 }
539 
540 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
541   if (_phase_times != NULL) {
542     _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
543     _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
544   }
545 }
546 
547 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
548                                                  G1ParScanThreadState* pss,
549                                                  G1GCPhaseTimes::GCParPhases phase,
550                                                  uint worker_id) :
551   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
552   _total_time(),
553   _trim_time(),
554   _trim_tracker(pss, _total_time, _trim_time) {
555 }
556 
557 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
558   if (_phase_times != NULL) {
559     // Explicitly stop the trim tracker since it's not yet destructed.
560     _trim_tracker.stop();
561     // Exclude trim time by increasing the start time.
562     _start_time += _trim_time;
563     _phase_times->record_or_add_objcopy_time_secs(_worker_id, _trim_time.seconds());
564   }
565 }
566 
--- EOF ---