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 #ifndef SHARE_VM_GC_G1_G1GCPHASETIMES_HPP
25 #define SHARE_VM_GC_G1_G1GCPHASETIMES_HPP
26 
27 #include "gc/shared/referenceProcessorPhaseTimes.hpp"
28 #include "gc/shared/weakProcessorPhaseTimes.hpp"
29 #include "jfr/jfrEvents.hpp"
30 #include "logging/logLevel.hpp"
31 #include "memory/allocation.hpp"
32 #include "utilities/macros.hpp"
33 
34 class LineBuffer;
35 class G1ParScanThreadState;
36 class STWGCTimer;
37 
38 template <class T> class WorkerDataArray;
39 
40 class G1GCPhaseTimes : public CHeapObj<mtGC> {
41   uint _max_gc_threads;
42   jlong _gc_start_counter;
43   double _gc_pause_time_ms;
44 
45  public:
46   enum GCParPhases {
47     GCWorkerStart,
48     ExtRootScan,
49     ThreadRoots,
50     StringTableRoots,
51     UniverseRoots,
52     JNIRoots,
53     ObjectSynchronizerRoots,
54     ManagementRoots,
55     SystemDictionaryRoots,
56     CLDGRoots,
57     JVMTIRoots,
58     CMRefRoots,
59     WaitForStrongCLD,
60     WeakCLDRoots,
61     SATBFiltering,
62     UpdateRS,
63     ScanHCC,
64     ScanRS,
65     CodeRoots,
66 #if INCLUDE_AOT
67     AOTCodeRoots,
68 #endif
69     ObjCopy,
70     Termination,
71     Other,
72     GCWorkerTotal,
73     GCWorkerEnd,
74     StringDedupQueueFixup,
75     StringDedupTableFixup,
76     RedirtyCards,
77     YoungFreeCSet,
78     NonYoungFreeCSet,
79     GCParPhasesSentinel
80   };
81 
82   enum GCScanRSWorkItems {
83     ScanRSScannedCards,
84     ScanRSClaimedCards,
85     ScanRSSkippedCards
86   };
87 
88   enum GCUpdateRSWorkItems {
89     UpdateRSProcessedBuffers,
90     UpdateRSScannedCards,
91     UpdateRSSkippedCards
92   };
93 
94  private:
95   // Markers for grouping the phases in the GCPhases enum above
96   static const int GCMainParPhasesLast = GCWorkerEnd;
97   static const int StringDedupPhasesFirst = StringDedupQueueFixup;
98   static const int StringDedupPhasesLast = StringDedupTableFixup;
99 
100   WorkerDataArray<double>* _gc_par_phases[GCParPhasesSentinel];
101 
102   WorkerDataArray<size_t>* _update_rs_processed_buffers;
103   WorkerDataArray<size_t>* _update_rs_scanned_cards;
104   WorkerDataArray<size_t>* _update_rs_skipped_cards;
105 
106   WorkerDataArray<size_t>* _scan_rs_scanned_cards;
107   WorkerDataArray<size_t>* _scan_rs_claimed_cards;
108   WorkerDataArray<size_t>* _scan_rs_skipped_cards;
109 
110   WorkerDataArray<size_t>* _termination_attempts;
111 
112   WorkerDataArray<size_t>* _redirtied_cards;
113 
114   double _cur_collection_par_time_ms;
115   double _cur_collection_code_root_fixup_time_ms;
116   double _cur_strong_code_root_purge_time_ms;
117 
118   double _cur_evac_fail_recalc_used;
119   double _cur_evac_fail_remove_self_forwards;
120 
121   double _cur_string_dedup_fixup_time_ms;
122 
123   double _cur_prepare_tlab_time_ms;
124   double _cur_resize_tlab_time_ms;
125 
126   double _cur_derived_pointer_table_update_time_ms;
127 
128   double _cur_clear_ct_time_ms;
129   double _cur_expand_heap_time_ms;
130   double _cur_ref_proc_time_ms;
131 
132   double _cur_collection_start_sec;
133   double _root_region_scan_wait_time_ms;
134 
135   double _external_accounted_time_ms;
136 
137   double _recorded_clear_claimed_marks_time_ms;
138 
139   double _recorded_young_cset_choice_time_ms;
140   double _recorded_non_young_cset_choice_time_ms;
141 
142   double _recorded_redirty_logged_cards_time_ms;
143 
144   double _recorded_preserve_cm_referents_time_ms;
145 
146   double _recorded_merge_pss_time_ms;
147 
148   double _recorded_start_new_cset_time_ms;
149 
150   double _recorded_total_free_cset_time_ms;
151 
152   double _recorded_serial_free_cset_time_ms;
153 
154   double _cur_fast_reclaim_humongous_time_ms;
155   double _cur_fast_reclaim_humongous_register_time_ms;
156   size_t _cur_fast_reclaim_humongous_total;
157   size_t _cur_fast_reclaim_humongous_candidates;
158   size_t _cur_fast_reclaim_humongous_reclaimed;
159 
160   double _cur_verify_before_time_ms;
161   double _cur_verify_after_time_ms;
162 
163   ReferenceProcessorPhaseTimes _ref_phase_times;
164   WeakProcessorPhaseTimes _weak_phase_times;
165 
166   double worker_time(GCParPhases phase, uint worker);
167   void note_gc_end();
168   void reset();
169 
170   template <class T>
171   void details(T* phase, const char* indent) const;
172 
173   void log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const;
174   void debug_phase(WorkerDataArray<double>* phase) const;
175   void trace_phase(WorkerDataArray<double>* phase, bool print_sum = true) const;
176 
177   void info_time(const char* name, double value) const;
178   void debug_time(const char* name, double value) const;
179   // This will print logs for both 'gc+phases' and 'gc+phases+ref'.
180   void debug_time_for_reference(const char* name, double value) const;
181   void trace_time(const char* name, double value) const;
182   void trace_count(const char* name, size_t value) const;
183 
184   double print_pre_evacuate_collection_set() const;
185   double print_evacuate_collection_set() const;
186   double print_post_evacuate_collection_set() const;
187   void print_other(double accounted_ms) const;
188 
189  public:
190   G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads);
191   void note_gc_start();
192   void print();
193   static const char* phase_name(GCParPhases phase);
194 
195   // record the time a phase took in seconds
196   void record_time_secs(GCParPhases phase, uint worker_i, double secs);
197 
198   // add a number of seconds to a phase
199   void add_time_secs(GCParPhases phase, uint worker_i, double secs);
200 
201   void record_or_add_objcopy_time_secs(uint worker_i, double secs);
202 
203   void record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index = 0);
204 
205   // return the average time for a phase in milliseconds
206   double average_time_ms(GCParPhases phase);
207 
208   size_t sum_thread_work_items(GCParPhases phase, uint index = 0);
209 
210  public:
211 
212   void record_prepare_tlab_time_ms(double ms) {
213     _cur_prepare_tlab_time_ms = ms;
214   }
215 
216   void record_resize_tlab_time_ms(double ms) {
217     _cur_resize_tlab_time_ms = ms;
218   }
219 
220   void record_derived_pointer_table_update_time(double ms) {
221     _cur_derived_pointer_table_update_time_ms = ms;
222   }
223 
224   void record_clear_ct_time(double ms) {
225     _cur_clear_ct_time_ms = ms;
226   }
227 
228   void record_expand_heap_time(double ms) {
229     _cur_expand_heap_time_ms = ms;
230   }
231 
232   void record_par_time(double ms) {
233     _cur_collection_par_time_ms = ms;
234   }
235 
236   void record_code_root_fixup_time(double ms) {
237     _cur_collection_code_root_fixup_time_ms = ms;
238   }
239 
240   void record_strong_code_root_purge_time(double ms) {
241     _cur_strong_code_root_purge_time_ms = ms;
242   }
243 
244   void record_evac_fail_recalc_used_time(double ms) {
245     _cur_evac_fail_recalc_used = ms;
246   }
247 
248   void record_evac_fail_remove_self_forwards(double ms) {
249     _cur_evac_fail_remove_self_forwards = ms;
250   }
251 
252   void record_string_dedup_fixup_time(double ms) {
253     _cur_string_dedup_fixup_time_ms = ms;
254   }
255 
256   void record_ref_proc_time(double ms) {
257     _cur_ref_proc_time_ms = ms;
258   }
259 
260   void record_root_region_scan_wait_time(double time_ms) {
261     _root_region_scan_wait_time_ms = time_ms;
262   }
263 
264   void record_total_free_cset_time_ms(double time_ms) {
265     _recorded_total_free_cset_time_ms = time_ms;
266   }
267 
268   void record_serial_free_cset_time_ms(double time_ms) {
269     _recorded_serial_free_cset_time_ms = time_ms;
270   }
271 
272   void record_fast_reclaim_humongous_stats(double time_ms, size_t total, size_t candidates) {
273     _cur_fast_reclaim_humongous_register_time_ms = time_ms;
274     _cur_fast_reclaim_humongous_total = total;
275     _cur_fast_reclaim_humongous_candidates = candidates;
276   }
277 
278   void record_fast_reclaim_humongous_time_ms(double value, size_t reclaimed) {
279     _cur_fast_reclaim_humongous_time_ms = value;
280     _cur_fast_reclaim_humongous_reclaimed = reclaimed;
281   }
282 
283   void record_young_cset_choice_time_ms(double time_ms) {
284     _recorded_young_cset_choice_time_ms = time_ms;
285   }
286 
287   void record_non_young_cset_choice_time_ms(double time_ms) {
288     _recorded_non_young_cset_choice_time_ms = time_ms;
289   }
290 
291   void record_redirty_logged_cards_time_ms(double time_ms) {
292     _recorded_redirty_logged_cards_time_ms = time_ms;
293   }
294 
295   void record_preserve_cm_referents_time_ms(double time_ms) {
296     _recorded_preserve_cm_referents_time_ms = time_ms;
297   }
298 
299   void record_merge_pss_time_ms(double time_ms) {
300     _recorded_merge_pss_time_ms = time_ms;
301   }
302 
303   void record_start_new_cset_time_ms(double time_ms) {
304     _recorded_start_new_cset_time_ms = time_ms;
305   }
306 
307   void record_cur_collection_start_sec(double time_ms) {
308     _cur_collection_start_sec = time_ms;
309   }
310 
311   void record_verify_before_time_ms(double time_ms) {
312     _cur_verify_before_time_ms = time_ms;
313   }
314 
315   void record_verify_after_time_ms(double time_ms) {
316     _cur_verify_after_time_ms = time_ms;
317   }
318 
319   void inc_external_accounted_time_ms(double time_ms) {
320     _external_accounted_time_ms += time_ms;
321   }
322 
323   void record_clear_claimed_marks_time_ms(double recorded_clear_claimed_marks_time_ms) {
324     _recorded_clear_claimed_marks_time_ms = recorded_clear_claimed_marks_time_ms;
325   }
326 
327   double cur_collection_start_sec() {
328     return _cur_collection_start_sec;
329   }
330 
331   double cur_collection_par_time_ms() {
332     return _cur_collection_par_time_ms;
333   }
334 
335   double cur_clear_ct_time_ms() {
336     return _cur_clear_ct_time_ms;
337   }
338 
339   double cur_expand_heap_time_ms() {
340     return _cur_expand_heap_time_ms;
341   }
342 
343   double root_region_scan_wait_time_ms() {
344     return _root_region_scan_wait_time_ms;
345   }
346 
347   double young_cset_choice_time_ms() {
348     return _recorded_young_cset_choice_time_ms;
349   }
350 
351   double total_free_cset_time_ms() {
352     return _recorded_total_free_cset_time_ms;
353   }
354 
355   double non_young_cset_choice_time_ms() {
356     return _recorded_non_young_cset_choice_time_ms;
357   }
358 
359   double fast_reclaim_humongous_time_ms() {
360     return _cur_fast_reclaim_humongous_time_ms;
361   }
362 
363   ReferenceProcessorPhaseTimes* ref_phase_times() { return &_ref_phase_times; }
364 
365   WeakProcessorPhaseTimes* weak_phase_times() { return &_weak_phase_times; }
366 };
367 
368 class G1EvacPhaseWithTrimTimeTracker : public StackObj {
369   G1ParScanThreadState* _pss;
370   Ticks _start;
371 
372   Tickspan& _total_time;
373   Tickspan& _trim_time;
374 
375   bool _stopped;
376 public:
377   G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time);
378   ~G1EvacPhaseWithTrimTimeTracker();
379 
380   void stop();
381 };
382 
383 class G1GCParPhaseTimesTracker : public CHeapObj<mtGC> {
384 protected:
385   Ticks _start_time;
386   G1GCPhaseTimes::GCParPhases _phase;
387   G1GCPhaseTimes* _phase_times;
388   uint _worker_id;
389   EventGCPhaseParallel _event;
390 public:
391   G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id);
392   virtual ~G1GCParPhaseTimesTracker();
393 };
394 
395 class G1EvacPhaseTimesTracker : public G1GCParPhaseTimesTracker {
396   Tickspan _total_time;
397   Tickspan _trim_time;
398 
399   G1EvacPhaseWithTrimTimeTracker _trim_tracker;
400 public:
401   G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1ParScanThreadState* pss, G1GCPhaseTimes::GCParPhases phase, uint w
402   virtual ~G1EvacPhaseTimesTracker();
403 };
404 
405 #endif // SHARE_VM_GC_G1_G1GCPHASETIMES_HPP
--- EOF ---