comparison src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp @ 6628:bb3f6194fedb

7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code Summary: Also reviewed by vitalyd@gmail.com. Introduced the WorkerDataArray class. Fixed some minor logging bugs. Reviewed-by: johnc, mgerdin
author brutisso
date Thu, 23 Aug 2012 10:21:12 +0200
parents 3a431b605145
children 7df93f7c14a5
comparison
equal deleted inserted replaced
6625:153776c4cb6f 6628:bb3f6194fedb
26 #define SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP 26 #define SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
27 27
28 #include "memory/allocation.hpp" 28 #include "memory/allocation.hpp"
29 #include "gc_interface/gcCause.hpp" 29 #include "gc_interface/gcCause.hpp"
30 30
31 template <class T>
32 class WorkerDataArray : public CHeapObj<mtGC> {
33 T* _data;
34 uint _length;
35 const char* _print_format;
36 bool _print_sum;
37
38 // We are caching the sum and average to only have to calculate them once.
39 // This is not done in an MT-safe way. It is intetened to allow single
40 // threaded code to call sum() and average() multiple times in any order
41 // without having to worry about the cost.
42 bool _has_new_data;
43 T _sum;
44 double _average;
45
46 public:
47 WorkerDataArray(uint length, const char* print_format, bool print_sum = true) :
48 _length(length), _print_format(print_format), _print_sum(print_sum), _has_new_data(true) {
49 assert(length > 0, "Must have some workers to store data for");
50 _data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
51 }
52
53 ~WorkerDataArray() {
54 FREE_C_HEAP_ARRAY(T, _data, mtGC);
55 }
56
57 void set(uint worker_i, T value) {
58 assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
59 assert(_data[worker_i] == (T)-1, err_msg("Overwriting data for worker %d", worker_i));
60 _data[worker_i] = value;
61 _has_new_data = true;
62 }
63
64 T get(uint worker_i) {
65 assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
66 assert(_data[worker_i] != (T)-1, err_msg("No data to add to for worker %d", worker_i));
67 return _data[worker_i];
68 }
69
70 void add(uint worker_i, T value) {
71 assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
72 assert(_data[worker_i] != (T)-1, err_msg("No data to add to for worker %d", worker_i));
73 _data[worker_i] += value;
74 _has_new_data = true;
75 }
76
77 double average(){
78 if (_has_new_data) {
79 calculate_totals();
80 }
81 return _average;
82 }
83
84 T sum() {
85 if (_has_new_data) {
86 calculate_totals();
87 }
88 return _sum;
89 }
90
91 void print(int level, const char* title);
92
93 void reset() PRODUCT_RETURN;
94 void verify() PRODUCT_RETURN;
95
96 private:
97
98 void calculate_totals(){
99 _sum = (T)0;
100 for (uint i = 0; i < _length; ++i) {
101 _sum += _data[i];
102 }
103 _average = (double)_sum / (double)_length;
104 _has_new_data = false;
105 }
106 };
107
31 class G1GCPhaseTimes : public CHeapObj<mtGC> { 108 class G1GCPhaseTimes : public CHeapObj<mtGC> {
32 friend class G1CollectorPolicy;
33 friend class TraceGen0TimeData;
34 109
35 private: 110 private:
36 uint _active_gc_threads; 111 uint _active_gc_threads;
37 uint _max_gc_threads; 112 uint _max_gc_threads;
38 113
39 GCCause::Cause _gc_cause; 114 WorkerDataArray<double> _last_gc_worker_start_times_ms;
40 bool _is_young_gc; 115 WorkerDataArray<double> _last_ext_root_scan_times_ms;
41 bool _is_initial_mark_gc; 116 WorkerDataArray<double> _last_satb_filtering_times_ms;
42 117 WorkerDataArray<double> _last_update_rs_times_ms;
43 double _pause_start_time_sec; 118 WorkerDataArray<int> _last_update_rs_processed_buffers;
44 119 WorkerDataArray<double> _last_scan_rs_times_ms;
45 double* _par_last_gc_worker_start_times_ms; 120 WorkerDataArray<double> _last_obj_copy_times_ms;
46 double* _par_last_ext_root_scan_times_ms; 121 WorkerDataArray<double> _last_termination_times_ms;
47 double* _par_last_satb_filtering_times_ms; 122 WorkerDataArray<size_t> _last_termination_attempts;
48 double* _par_last_update_rs_times_ms; 123 WorkerDataArray<double> _last_gc_worker_end_times_ms;
49 double* _par_last_update_rs_processed_buffers; 124 WorkerDataArray<double> _last_gc_worker_times_ms;
50 double* _par_last_scan_rs_times_ms; 125 WorkerDataArray<double> _last_gc_worker_other_times_ms;
51 double* _par_last_obj_copy_times_ms;
52 double* _par_last_termination_times_ms;
53 double* _par_last_termination_attempts;
54 double* _par_last_gc_worker_end_times_ms;
55 double* _par_last_gc_worker_times_ms;
56 double* _par_last_gc_worker_other_times_ms;
57 126
58 double _cur_collection_par_time_ms; 127 double _cur_collection_par_time_ms;
59
60 double _cur_collection_code_root_fixup_time_ms; 128 double _cur_collection_code_root_fixup_time_ms;
61 129
62 double _cur_clear_ct_time_ms; 130 double _cur_clear_ct_time_ms;
63 double _cur_ref_proc_time_ms; 131 double _cur_ref_proc_time_ms;
64 double _cur_ref_enq_time_ms; 132 double _cur_ref_enq_time_ms;
65
66 // Helper methods for detailed logging
67 void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
68 void print_stats(int level, const char* str, double value);
69 void print_stats(int level, const char* str, double value, int workers);
70 void print_stats(int level, const char* str, int value);
71 double avg_value(double* data);
72 double max_value(double* data);
73 double sum_of_values(double* data);
74 double max_sum(double* data1, double* data2);
75 double accounted_time_ms();
76 133
77 // Card Table Count Cache stats 134 // Card Table Count Cache stats
78 double _min_clear_cc_time_ms; // min 135 double _min_clear_cc_time_ms; // min
79 double _max_clear_cc_time_ms; // max 136 double _max_clear_cc_time_ms; // max
80 double _cur_clear_cc_time_ms; // clearing time during current pause 137 double _cur_clear_cc_time_ms; // clearing time during current pause
81 double _cum_clear_cc_time_ms; // cummulative clearing time 138 double _cum_clear_cc_time_ms; // cummulative clearing time
82 jlong _num_cc_clears; // number of times the card count cache has been cleared 139 jlong _num_cc_clears; // number of times the card count cache has been cleared
83 140
84 // The following insance variables are directly accessed by G1CollectorPolicy
85 // and TraceGen0TimeData. This is why those classes are declared friends.
86 // An alternative is to add getters and setters for all of these fields.
87 // It might also be possible to restructure the code to reduce these
88 // dependencies.
89 double _ext_root_scan_time;
90 double _satb_filtering_time;
91 double _update_rs_time;
92 double _update_rs_processed_buffers;
93 double _scan_rs_time;
94 double _obj_copy_time;
95 double _termination_time;
96
97 double _cur_collection_start_sec; 141 double _cur_collection_start_sec;
98 double _root_region_scan_wait_time_ms; 142 double _root_region_scan_wait_time_ms;
99 143
100 double _recorded_young_cset_choice_time_ms; 144 double _recorded_young_cset_choice_time_ms;
101 double _recorded_non_young_cset_choice_time_ms; 145 double _recorded_non_young_cset_choice_time_ms;
102 146
103 double _recorded_young_free_cset_time_ms; 147 double _recorded_young_free_cset_time_ms;
104 double _recorded_non_young_free_cset_time_ms; 148 double _recorded_non_young_free_cset_time_ms;
105 149
106 void print(double pause_time_ms); 150 double _cur_verify_before_time_ms;
151 double _cur_verify_after_time_ms;
152
153 // Helper methods for detailed logging
154 void print_stats(int level, const char* str, double value);
155 void print_stats(int level, const char* str, double value, int workers);
107 156
108 public: 157 public:
109 G1GCPhaseTimes(uint max_gc_threads); 158 G1GCPhaseTimes(uint max_gc_threads);
110 void note_gc_start(double pause_start_time_sec, uint active_gc_threads, 159 void note_gc_start(uint active_gc_threads);
111 bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause); 160 void note_gc_end();
112 void note_gc_end(double pause_end_time_sec); 161 void print(double pause_time_sec);
113 void collapse_par_times();
114 162
115 void record_gc_worker_start_time(uint worker_i, double ms) { 163 void record_gc_worker_start_time(uint worker_i, double ms) {
116 assert(worker_i >= 0, "worker index must be > 0"); 164 _last_gc_worker_start_times_ms.set(worker_i, ms);
117 assert(worker_i < _active_gc_threads, "worker index out of bounds");
118 _par_last_gc_worker_start_times_ms[worker_i] = ms;
119 } 165 }
120 166
121 void record_ext_root_scan_time(uint worker_i, double ms) { 167 void record_ext_root_scan_time(uint worker_i, double ms) {
122 assert(worker_i >= 0, "worker index must be > 0"); 168 _last_ext_root_scan_times_ms.set(worker_i, ms);
123 assert(worker_i < _active_gc_threads, "worker index out of bounds");
124 _par_last_ext_root_scan_times_ms[worker_i] = ms;
125 } 169 }
126 170
127 void record_satb_filtering_time(uint worker_i, double ms) { 171 void record_satb_filtering_time(uint worker_i, double ms) {
128 assert(worker_i >= 0, "worker index must be > 0"); 172 _last_satb_filtering_times_ms.set(worker_i, ms);
129 assert(worker_i < _active_gc_threads, "worker index out of bounds");
130 _par_last_satb_filtering_times_ms[worker_i] = ms;
131 } 173 }
132 174
133 void record_update_rs_time(uint worker_i, double ms) { 175 void record_update_rs_time(uint worker_i, double ms) {
134 assert(worker_i >= 0, "worker index must be > 0"); 176 _last_update_rs_times_ms.set(worker_i, ms);
135 assert(worker_i < _active_gc_threads, "worker index out of bounds"); 177 }
136 _par_last_update_rs_times_ms[worker_i] = ms; 178
137 } 179 void record_update_rs_processed_buffers(uint worker_i, int processed_buffers) {
138 180 _last_update_rs_processed_buffers.set(worker_i, processed_buffers);
139 void record_update_rs_processed_buffers (uint worker_i,
140 double processed_buffers) {
141 assert(worker_i >= 0, "worker index must be > 0");
142 assert(worker_i < _active_gc_threads, "worker index out of bounds");
143 _par_last_update_rs_processed_buffers[worker_i] = processed_buffers;
144 } 181 }
145 182
146 void record_scan_rs_time(uint worker_i, double ms) { 183 void record_scan_rs_time(uint worker_i, double ms) {
147 assert(worker_i >= 0, "worker index must be > 0"); 184 _last_scan_rs_times_ms.set(worker_i, ms);
148 assert(worker_i < _active_gc_threads, "worker index out of bounds");
149 _par_last_scan_rs_times_ms[worker_i] = ms;
150 }
151
152 void reset_obj_copy_time(uint worker_i) {
153 assert(worker_i >= 0, "worker index must be > 0");
154 assert(worker_i < _active_gc_threads, "worker index out of bounds");
155 _par_last_obj_copy_times_ms[worker_i] = 0.0;
156 }
157
158 void reset_obj_copy_time() {
159 reset_obj_copy_time(0);
160 } 185 }
161 186
162 void record_obj_copy_time(uint worker_i, double ms) { 187 void record_obj_copy_time(uint worker_i, double ms) {
163 assert(worker_i >= 0, "worker index must be > 0"); 188 _last_obj_copy_times_ms.set(worker_i, ms);
164 assert(worker_i < _active_gc_threads, "worker index out of bounds"); 189 }
165 _par_last_obj_copy_times_ms[worker_i] += ms; 190
191 void add_obj_copy_time(uint worker_i, double ms) {
192 _last_obj_copy_times_ms.add(worker_i, ms);
166 } 193 }
167 194
168 void record_termination(uint worker_i, double ms, size_t attempts) { 195 void record_termination(uint worker_i, double ms, size_t attempts) {
169 assert(worker_i >= 0, "worker index must be > 0"); 196 _last_termination_times_ms.set(worker_i, ms);
170 assert(worker_i < _active_gc_threads, "worker index out of bounds"); 197 _last_termination_attempts.set(worker_i, attempts);
171 _par_last_termination_times_ms[worker_i] = ms;
172 _par_last_termination_attempts[worker_i] = (double) attempts;
173 } 198 }
174 199
175 void record_gc_worker_end_time(uint worker_i, double ms) { 200 void record_gc_worker_end_time(uint worker_i, double ms) {
176 assert(worker_i >= 0, "worker index must be > 0"); 201 _last_gc_worker_end_times_ms.set(worker_i, ms);
177 assert(worker_i < _active_gc_threads, "worker index out of bounds");
178 _par_last_gc_worker_end_times_ms[worker_i] = ms;
179 } 202 }
180 203
181 void record_clear_ct_time(double ms) { 204 void record_clear_ct_time(double ms) {
182 _cur_clear_ct_time_ms = ms; 205 _cur_clear_ct_time_ms = ms;
183 } 206 }
209 } 232 }
210 233
211 void record_non_young_free_cset_time_ms(double time_ms) { 234 void record_non_young_free_cset_time_ms(double time_ms) {
212 _recorded_non_young_free_cset_time_ms = time_ms; 235 _recorded_non_young_free_cset_time_ms = time_ms;
213 } 236 }
237
238 void record_young_cset_choice_time_ms(double time_ms) {
239 _recorded_young_cset_choice_time_ms = time_ms;
240 }
241
242 void record_non_young_cset_choice_time_ms(double time_ms) {
243 _recorded_non_young_cset_choice_time_ms = time_ms;
244 }
245
246 void record_cur_collection_start_sec(double time_ms) {
247 _cur_collection_start_sec = time_ms;
248 }
249
250 void record_verify_before_time_ms(double time_ms) {
251 _cur_verify_before_time_ms = time_ms;
252 }
253
254 void record_verify_after_time_ms(double time_ms) {
255 _cur_verify_after_time_ms = time_ms;
256 }
257
258 double accounted_time_ms();
259
260 double cur_collection_start_sec() {
261 return _cur_collection_start_sec;
262 }
263
264 double cur_collection_par_time_ms() {
265 return _cur_collection_par_time_ms;
266 }
267
268 double cur_clear_ct_time_ms() {
269 return _cur_clear_ct_time_ms;
270 }
271
272 double root_region_scan_wait_time_ms() {
273 return _root_region_scan_wait_time_ms;
274 }
275
276 double young_cset_choice_time_ms() {
277 return _recorded_young_cset_choice_time_ms;
278 }
279
280 double young_free_cset_time_ms() {
281 return _recorded_young_free_cset_time_ms;
282 }
283
284 double non_young_cset_choice_time_ms() {
285 return _recorded_non_young_cset_choice_time_ms;
286 }
287
288 double non_young_free_cset_time_ms() {
289 return _recorded_non_young_free_cset_time_ms;
290 }
291
292 double average_last_update_rs_time() {
293 return _last_update_rs_times_ms.average();
294 }
295
296 int sum_last_update_rs_processed_buffers() {
297 return _last_update_rs_processed_buffers.sum();
298 }
299
300 double average_last_scan_rs_time(){
301 return _last_scan_rs_times_ms.average();
302 }
303
304 double average_last_obj_copy_time() {
305 return _last_obj_copy_times_ms.average();
306 }
307
308 double average_last_termination_time() {
309 return _last_termination_times_ms.average();
310 }
311
312 double average_last_ext_root_scan_time() {
313 return _last_ext_root_scan_times_ms.average();
314 }
315
316 double average_last_satb_filtering_times_ms() {
317 return _last_satb_filtering_times_ms.average();
318 }
214 }; 319 };
215 320
216 #endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP 321 #endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP