77 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
78
79 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
80 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
81
82 if (UseStringDeduplication) {
83 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
84 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
85 } else {
86 _gc_par_phases[StringDedupQueueFixup] = NULL;
87 _gc_par_phases[StringDedupTableFixup] = NULL;
88 }
89
90 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
91 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
92 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
93
94 _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
95 }
96
97 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
98 assert(active_gc_threads > 0, "The number of threads must be > 0");
99 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
100 _gc_start_counter = os::elapsed_counter();
101 _active_gc_threads = active_gc_threads;
102 _cur_expand_heap_time_ms = 0.0;
103 _external_accounted_time_ms = 0.0;
104
105 for (int i = 0; i < GCParPhasesSentinel; i++) {
106 if (_gc_par_phases[i] != NULL) {
107 _gc_par_phases[i]->reset();
108 }
109 }
110 }
111
112 void G1GCPhaseTimes::note_gc_end() {
113 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
114 for (uint i = 0; i < _active_gc_threads; i++) {
115 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
116 record_time_secs(GCWorkerTotal, i , worker_time);
117
118 double worker_known_time =
119 _gc_par_phases[ExtRootScan]->get(i) +
120 _gc_par_phases[SATBFiltering]->get(i) +
121 _gc_par_phases[UpdateRS]->get(i) +
122 _gc_par_phases[ScanRS]->get(i) +
123 _gc_par_phases[CodeRoots]->get(i) +
124 _gc_par_phases[ObjCopy]->get(i) +
125 _gc_par_phases[Termination]->get(i);
126
127 record_time_secs(Other, i, worker_time - worker_known_time);
128 }
129
130 for (int i = 0; i < GCParPhasesSentinel; i++) {
131 if (_gc_par_phases[i] != NULL) {
132 _gc_par_phases[i]->verify(_active_gc_threads);
133 }
134 }
135 }
136
137 // record the time a phase took in seconds
138 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
139 _gc_par_phases[phase]->set(worker_i, secs);
140 }
141
142 // add a number of seconds to a phase
143 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
144 _gc_par_phases[phase]->add(worker_i, secs);
145 }
146
147 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) {
148 _gc_par_phases[phase]->set_thread_work_item(worker_i, count);
149 }
150
151 // return the average time for a phase in milliseconds
152 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
153 return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
154 }
155
156 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
157 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
158 return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
159 }
160
161 template <class T>
162 void G1GCPhaseTimes::details(T* phase, const char* indent) {
163 LogHandle(gc, phases, task) log;
164 if (log.is_level(LogLevel::Trace)) {
165 outputStream* trace_out = log.trace_stream();
166 trace_out->print("%s", indent);
167 phase->print_details_on(trace_out, _active_gc_threads);
168 }
169 }
170
171 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
172 out->print("%s", Indents[indent]);
173 phase->print_summary_on(out, _active_gc_threads, print_sum);
174 details(phase, Indents[indent]);
175
176 WorkerDataArray<size_t>* work_items = phase->thread_work_items();
177 if (work_items != NULL) {
178 out->print("%s", Indents[indent + 1]);
179 work_items->print_summary_on(out, _active_gc_threads, true);
180 details(work_items, Indents[indent + 1]);
181 }
182 }
183
184 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
185 LogHandle(gc, phases) log;
186 if (log.is_level(LogLevel::Debug)) {
187 ResourceMark rm;
188 log_phase(phase, 2, log.debug_stream(), true);
189 }
190 }
191
192 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) {
193 LogHandle(gc, phases) log;
194 if (log.is_level(LogLevel::Trace)) {
195 ResourceMark rm;
196 log_phase(phase, 3, log.trace_stream(), print_sum);
197 }
198 }
199
|
77 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
78
79 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
80 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
81
82 if (UseStringDeduplication) {
83 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
84 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
85 } else {
86 _gc_par_phases[StringDedupQueueFixup] = NULL;
87 _gc_par_phases[StringDedupTableFixup] = NULL;
88 }
89
90 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
91 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
92 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
93
94 _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
95 }
96
97 void G1GCPhaseTimes::note_gc_start() {
98 _gc_start_counter = os::elapsed_counter();
99 _cur_expand_heap_time_ms = 0.0;
100 _external_accounted_time_ms = 0.0;
101
102 for (int i = 0; i < GCParPhasesSentinel; i++) {
103 if (_gc_par_phases[i] != NULL) {
104 _gc_par_phases[i]->reset();
105 }
106 }
107 }
108
109 #define ASSERT_PHASE_UNINITILIAZED(phase) \
110 assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
111
112 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
113 double value = _gc_par_phases[phase]->get(worker);
114 if (value != WorkerDataArray<double>::uninitialized()) {
115 return value;
116 }
117 return 0.0;
118 }
119
120 void G1GCPhaseTimes::note_gc_end() {
121 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
122
123 double uninitialized = WorkerDataArray<double>::uninitialized();
124
125 for (uint i = 0; i < _max_gc_threads; i++) {
126 double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
127 if (worker_start != uninitialized) {
128 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
129 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
130 record_time_secs(GCWorkerTotal, i , total_worker_time);
131
132 double worker_known_time =
133 worker_time(ExtRootScan, i)
134 + worker_time(SATBFiltering, i)
135 + worker_time(UpdateRS, i)
136 + worker_time(ScanRS, i)
137 + worker_time(CodeRoots, i)
138 + worker_time(ObjCopy, i)
139 + worker_time(Termination, i);
140
141 record_time_secs(Other, i, total_worker_time - worker_known_time);
142 } else {
143 // Make sure all slots are uninitialized since this thread did not seem to have been started
144 ASSERT_PHASE_UNINITILIAZED(GCWorkerEnd);
145 ASSERT_PHASE_UNINITILIAZED(ExtRootScan);
146 ASSERT_PHASE_UNINITILIAZED(SATBFiltering);
147 ASSERT_PHASE_UNINITILIAZED(UpdateRS);
148 ASSERT_PHASE_UNINITILIAZED(ScanRS);
149 ASSERT_PHASE_UNINITILIAZED(CodeRoots);
150 ASSERT_PHASE_UNINITILIAZED(ObjCopy);
151 ASSERT_PHASE_UNINITILIAZED(Termination);
152 }
153 }
154 }
155
156 #undef ASSERT_PHASE_UNINITILIAZED
157
158 // record the time a phase took in seconds
159 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
160 _gc_par_phases[phase]->set(worker_i, secs);
161 }
162
163 // add a number of seconds to a phase
164 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
165 _gc_par_phases[phase]->add(worker_i, secs);
166 }
167
168 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) {
169 _gc_par_phases[phase]->set_thread_work_item(worker_i, count);
170 }
171
172 // return the average time for a phase in milliseconds
173 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
174 return _gc_par_phases[phase]->average() * 1000.0;
175 }
176
177 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
178 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
179 return _gc_par_phases[phase]->thread_work_items()->sum();
180 }
181
182 template <class T>
183 void G1GCPhaseTimes::details(T* phase, const char* indent) {
184 LogHandle(gc, phases, task) log;
185 if (log.is_level(LogLevel::Trace)) {
186 outputStream* trace_out = log.trace_stream();
187 trace_out->print("%s", indent);
188 phase->print_details_on(trace_out);
189 }
190 }
191
192 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
193 out->print("%s", Indents[indent]);
194 phase->print_summary_on(out, print_sum);
195 details(phase, Indents[indent]);
196
197 WorkerDataArray<size_t>* work_items = phase->thread_work_items();
198 if (work_items != NULL) {
199 out->print("%s", Indents[indent + 1]);
200 work_items->print_summary_on(out, true);
201 details(work_items, Indents[indent + 1]);
202 }
203 }
204
205 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
206 LogHandle(gc, phases) log;
207 if (log.is_level(LogLevel::Debug)) {
208 ResourceMark rm;
209 log_phase(phase, 2, log.debug_stream(), true);
210 }
211 }
212
213 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) {
214 LogHandle(gc, phases) log;
215 if (log.is_level(LogLevel::Trace)) {
216 ResourceMark rm;
217 log_phase(phase, 3, log.trace_stream(), print_sum);
218 }
219 }
220
|