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
26 #include "gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp"
27 #include "gc_implementation/shenandoah/shenandoahPhaseTimings.hpp"
28 #include "gc_implementation/shenandoah/shenandoahHeap.hpp"
29 #include "gc_implementation/shenandoah/shenandoahWorkerDataArray.hpp"
30 #include "utilities/ostream.hpp"
31
32 ShenandoahPhaseTimings::ShenandoahPhaseTimings() : _policy(NULL) {
33 _worker_times = new ShenandoahWorkerTimings((uint)MAX2(ConcGCThreads, ParallelGCThreads));
34 _policy = ShenandoahHeap::heap()->shenandoahPolicy();
35 assert(_policy != NULL, "Can not be NULL");
36 init_phase_names();
37 }
38
39 void ShenandoahPhaseTimings::record_phase_start(Phase phase) {
40 _timing_data[phase]._start = os::elapsedTime();
41 }
42
43 void ShenandoahPhaseTimings::record_phase_end(Phase phase) {
44 assert(_policy != NULL, "Not yet initialized");
45 double end = os::elapsedTime();
46 double elapsed = end - _timing_data[phase]._start;
47 if (!_policy->is_at_shutdown()) {
48 _timing_data[phase]._secs.add(elapsed);
49 }
50 _policy->record_phase_time(phase, elapsed);
51 }
52
53 void ShenandoahPhaseTimings::record_phase_time(Phase phase, jint time_us) {
54 assert(_policy != NULL, "Not yet initialized");
55 if (!_policy->is_at_shutdown()) {
56 _timing_data[phase]._secs.add((double)time_us / 1000 / 1000);
57 }
58 }
59
60 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
61 for (uint i = 0; i < GCParPhasesSentinel; i++) {
62 _worker_times->reset(i);
63 }
64 }
65
66 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
67 if (_policy->is_at_shutdown()) {
68 // Do not record the past-shutdown events
69 return;
70 }
71
72 guarantee(phase == init_evac ||
73 phase == scan_roots ||
74 phase == update_roots ||
75 phase == partial_gc_work ||
76 phase == final_update_refs_roots ||
77 phase == full_gc_roots ||
78 phase == _num_phases,
79 "only in these phases we can add per-thread phase times");
80 if (phase != _num_phases) {
81 // Merge _phase_time to counters below the given phase.
82 for (uint i = 0; i < GCParPhasesSentinel; i++) {
83 double t = _worker_times->average(i);
84 _timing_data[phase + i + 1]._secs.add(t);
85 }
86 }
87 }
88
89 void ShenandoahPhaseTimings::print_on(outputStream* out) const {
90 out->cr();
91 out->print_cr("GC STATISTICS:");
92 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
93 out->print_cr(" and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect.");
94 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code.");
95 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense.");
96 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
97 out->cr();
98
99 for (uint i = 0; i < _num_phases; i++) {
100 if (_timing_data[i]._secs.maximum() != 0) {
101 print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs));
102 }
103 }
104 }
105
106 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const {
107 out->print_cr("%-27s = %8.2lf s (a = %8.0lf us) (n = "INT32_FORMAT_W(5)") (lvls, us = %8.0lf, %8.0lf, %8.0lf, %8.0lf, %8.0lf)",
108 str,
109 seq->sum(),
110 seq->avg() * 1000000.0,
111 seq->num(),
112 seq->percentile(0) * 1000000.0,
113 seq->percentile(25) * 1000000.0,
114 seq->percentile(50) * 1000000.0,
115 seq->percentile(75) * 1000000.0,
116 seq->maximum() * 1000000.0
117 );
118 }
119
120 void ShenandoahPhaseTimings::init_phase_names() {
121 _phase_names[total_pause] = "Total Pauses (N)";
122 _phase_names[total_pause_gross] = "Total Pauses (G)";
123 _phase_names[init_mark] = "Pause Init Mark (N)";
124 _phase_names[init_mark_gross] = "Pause Init Mark (G)";
125 _phase_names[final_mark] = "Pause Final Mark (N)";
126 _phase_names[final_mark_gross] = "Pause Final Mark (G)";
127 _phase_names[final_evac] = "Pause Final Evac (N)";
128 _phase_names[final_evac_gross] = "Pause Final Evac (G)";
129 _phase_names[accumulate_stats] = " Accumulate Stats";
130 _phase_names[make_parsable] = " Make Parsable";
131 _phase_names[clear_liveness] = " Clear Liveness";
132 _phase_names[resize_tlabs] = " Resize TLABs";
133 _phase_names[finish_queues] = " Finish Queues";
134 _phase_names[weakrefs] = " Weak References";
135 _phase_names[weakrefs_process] = " Process";
136 _phase_names[weakrefs_enqueue] = " Enqueue";
137 _phase_names[purge] = " System Purge";
138 _phase_names[purge_class_unload] = " Unload Classes";
139 _phase_names[purge_par] = " Parallel Cleanup";
140 _phase_names[purge_par_codecache] = " Code Cache";
141 _phase_names[purge_par_symbstring] = " String/Symbol Tables";
142 _phase_names[purge_par_rmt] = " Resolved Methods";
143 _phase_names[purge_par_classes] = " Clean Classes";
144 _phase_names[purge_par_sync] = " Synchronization";
145 _phase_names[purge_cldg] = " CLDG";
146 _phase_names[clean_str_dedup_table] = " String Dedup Table";
147 _phase_names[prepare_evac] = " Prepare Evacuation";
148
149 _phase_names[scan_roots] = " Scan Roots";
150 _phase_names[scan_thread_roots] = " S: Thread Roots";
151 _phase_names[scan_code_roots] = " S: Code Cache Roots";
152 _phase_names[scan_string_table_roots] = " S: String Table Roots";
153 _phase_names[scan_universe_roots] = " S: Universe Roots";
154 _phase_names[scan_jni_roots] = " S: JNI Roots";
155 _phase_names[scan_jni_weak_roots] = " S: JNI Weak Roots";
156 _phase_names[scan_synchronizer_roots] = " S: Synchronizer Roots";
157 _phase_names[scan_flat_profiler_roots] = " S: Flat Profiler Roots";
158 _phase_names[scan_management_roots] = " S: Management Roots";
159 _phase_names[scan_system_dictionary_roots] = " S: System Dict Roots";
160 _phase_names[scan_cldg_roots] = " S: CLDG Roots";
161 _phase_names[scan_jvmti_roots] = " S: JVMTI Roots";
162 _phase_names[scan_finish_queues] = " S: Finish Queues";
163
164 _phase_names[update_roots] = " Update Roots";
165 _phase_names[update_thread_roots] = " U: Thread Roots";
166 _phase_names[update_code_roots] = " U: Code Cache Roots";
167 _phase_names[update_string_table_roots] = " U: String Table Roots";
168 _phase_names[update_universe_roots] = " U: Universe Roots";
169 _phase_names[update_jni_roots] = " U: JNI Roots";
170 _phase_names[update_jni_weak_roots] = " U: JNI Weak Roots";
171 _phase_names[update_synchronizer_roots] = " U: Synchronizer Roots";
172 _phase_names[update_flat_profiler_roots] = " U: Flat Profiler Roots";
173 _phase_names[update_management_roots] = " U: Management Roots";
174 _phase_names[update_system_dictionary_roots] = " U: System Dict Roots";
175 _phase_names[update_cldg_roots] = " U: CLDG Roots";
176 _phase_names[update_jvmti_roots] = " U: JVMTI Roots";
177 _phase_names[update_finish_queues] = " U: Finish Queues";
178
179 _phase_names[init_evac] = " Initial Evacuation";
180 _phase_names[evac_thread_roots] = " E: Thread Roots";
181 _phase_names[evac_code_roots] = " E: Code Cache Roots";
182 _phase_names[evac_string_table_roots] = " E: String Table Roots";
183 _phase_names[evac_universe_roots] = " E: Universe Roots";
184 _phase_names[evac_jni_roots] = " E: JNI Roots";
185 _phase_names[evac_jni_weak_roots] = " E: JNI Weak Roots";
186 _phase_names[evac_synchronizer_roots] = " E: Synchronizer Roots";
187 _phase_names[evac_flat_profiler_roots] = " E: Flat Profiler Roots";
188 _phase_names[evac_management_roots] = " E: Management Roots";
189 _phase_names[evac_system_dictionary_roots] = " E: System Dict Roots";
190 _phase_names[evac_cldg_roots] = " E: CLDG Roots";
191 _phase_names[evac_jvmti_roots] = " E: JVMTI Roots";
192 _phase_names[evac_finish_queues] = " E: Finish Queues";
193
194 _phase_names[recycle_regions] = " Recycle regions";
195
196 _phase_names[degen_gc_gross] = "Pause Degenerated GC (G)";
197 _phase_names[degen_gc] = "Pause Degenerated GC (N)";
198
199 _phase_names[full_gc_gross] = "Pause Full GC (G)";
200 _phase_names[full_gc] = "Pause Full GC (N)";
201 _phase_names[full_gc_heapdumps] = " Heap Dumps";
202 _phase_names[full_gc_prepare] = " Prepare";
203 _phase_names[full_gc_roots] = " Roots";
204 _phase_names[full_gc_thread_roots] = " F: Thread Roots";
205 _phase_names[full_gc_code_roots] = " F: Code Cache Roots";
206 _phase_names[full_gc_string_table_roots] = " F: String Table Roots";
207 _phase_names[full_gc_universe_roots] = " F: Universe Roots";
208 _phase_names[full_gc_jni_roots] = " F: JNI Roots";
209 _phase_names[full_gc_jni_weak_roots] = " F: JNI Weak Roots";
210 _phase_names[full_gc_synchronizer_roots] = " F: Synchronizer Roots";
211 _phase_names[full_gc_flat_profiler_roots] = " F: Flat Profiler Roots";
212 _phase_names[full_gc_management_roots] = " F: Management Roots";
213 _phase_names[full_gc_system_dictionary_roots] = " F: System Dict Roots";
214 _phase_names[full_gc_cldg_roots] = " F: CLDG Roots";
215 _phase_names[full_gc_jvmti_roots] = " F: JVMTI Roots";
216 _phase_names[full_gc_finish_queues] = " F: Finish Queues";
217 _phase_names[full_gc_mark] = " Mark";
218 _phase_names[full_gc_mark_finish_queues] = " Finish Queues";
219 _phase_names[full_gc_weakrefs] = " Weak References";
220 _phase_names[full_gc_weakrefs_process] = " Process";
221 _phase_names[full_gc_weakrefs_enqueue] = " Enqueue";
222 _phase_names[full_gc_purge] = " System Purge";
223 _phase_names[full_gc_purge_class_unload] = " Unload Classes";
224 _phase_names[full_gc_purge_par] = " Parallel Cleanup";
225 _phase_names[full_gc_purge_par_codecache] = " Code Cache";
226 _phase_names[full_gc_purge_par_symbstring] = " String/Symbol Tables";
227 _phase_names[full_gc_purge_par_rmt] = " Resolved Methods";
228 _phase_names[full_gc_purge_par_classes] = " Clean Classes";
229 _phase_names[full_gc_purge_par_sync] = " Synchronization";
230 _phase_names[full_gc_purge_cldg] = " CLDG";
231 _phase_names[full_gc_calculate_addresses] = " Calculate Addresses";
232 _phase_names[full_gc_calculate_addresses_regular] = " Regular Objects";
233 _phase_names[full_gc_calculate_addresses_humong] = " Humongous Objects";
234 _phase_names[full_gc_adjust_pointers] = " Adjust Pointers";
235 _phase_names[full_gc_copy_objects] = " Copy Objects";
236 _phase_names[full_gc_copy_objects_regular] = " Regular Objects";
237 _phase_names[full_gc_copy_objects_humong] = " Humongous Objects";
238 _phase_names[full_gc_update_str_dedup_table] = " Update String Dedup Table";
239 _phase_names[full_gc_resize_tlabs] = " Resize TLABs";
240
241 _phase_names[partial_gc_gross] = "Pause Partial GC (G)";
242 _phase_names[partial_gc] = "Pause Partial GC (N)";
243 _phase_names[partial_gc_prepare] = " Prepare";
244 _phase_names[partial_gc_work] = " Work";
245 _phase_names[partial_gc_thread_roots] = " P: Thread Roots";
246 _phase_names[partial_gc_code_roots] = " P: Code Cache Roots";
247 _phase_names[partial_gc_string_table_roots] = " P: String Table Roots";
248 _phase_names[partial_gc_universe_roots] = " P: Universe Roots";
249 _phase_names[partial_gc_jni_roots] = " P: JNI Roots";
250 _phase_names[partial_gc_jni_weak_roots] = " P: JNI Weak Roots";
251 _phase_names[partial_gc_synchronizer_roots] = " P: Synchronizer Roots";
252 _phase_names[partial_gc_flat_profiler_roots] = " P: Flat Profiler Roots";
253 _phase_names[partial_gc_management_roots] = " P: Management Roots";
254 _phase_names[partial_gc_system_dict_roots] = " P: System Dict Roots";
255 _phase_names[partial_gc_cldg_roots] = " P: CLDG Roots";
256 _phase_names[partial_gc_jvmti_roots] = " P: JVMTI Roots";
257 _phase_names[partial_gc_update_str_dedup_table]
258 = " Update String Dedup Table";
259 _phase_names[partial_gc_recycle] = " Recycle";
260
261 _phase_names[pause_other] = "Pause Other";
262
263 _phase_names[conc_mark] = "Concurrent Marking";
264 _phase_names[conc_preclean] = "Concurrent Precleaning";
265 _phase_names[conc_evac] = "Concurrent Evacuation";
266 _phase_names[conc_cleanup] = "Concurrent Cleanup";
267 _phase_names[conc_cleanup_recycle] = " Recycle";
268 _phase_names[conc_cleanup_reset_bitmaps] = " Reset Bitmaps";
269 _phase_names[conc_other] = "Concurrent Other";
270
271 _phase_names[init_update_refs_gross] = "Pause Init Update Refs (G)";
272 _phase_names[init_update_refs] = "Pause Init Update Refs (N)";
273 _phase_names[conc_update_refs] = "Concurrent Update Refs";
274 _phase_names[final_update_refs_gross] = "Pause Final Update Refs (G)";
275 _phase_names[final_update_refs] = "Pause Final Update Refs (N)";
276
277 _phase_names[final_update_refs_finish_work] = " Finish Work";
278 _phase_names[final_update_refs_roots] = " Update Roots";
279 _phase_names[final_update_refs_thread_roots] = " UR: Thread Roots";
280 _phase_names[final_update_refs_code_roots] = " UR: Code Cache Roots";
281 _phase_names[final_update_refs_string_table_roots] = " UR: String Table Roots";
282 _phase_names[final_update_refs_universe_roots] = " UR: Universe Roots";
283 _phase_names[final_update_refs_jni_roots] = " UR: JNI Roots";
284 _phase_names[final_update_refs_jni_weak_roots] = " UR: JNI Weak Roots";
285 _phase_names[final_update_refs_synchronizer_roots] = " UR: Synchronizer Roots";
286 _phase_names[final_update_refs_flat_profiler_roots] = " UR: Flat Profiler Roots";
287 _phase_names[final_update_refs_management_roots] = " UR: Management Roots";
288 _phase_names[final_update_refs_system_dict_roots] = " UR: System Dict Roots";
289 _phase_names[final_update_refs_cldg_roots] = " UR: CLDG Roots";
290 _phase_names[final_update_refs_jvmti_roots] = " UR: JVMTI Roots";
291 _phase_names[final_update_refs_finish_queues] = " UR: Finish Queues";
292 _phase_names[final_update_refs_recycle] = " Recycle";
293 }
294
295 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) :
296 _max_gc_threads(max_gc_threads)
297 {
298 assert(max_gc_threads > 0, "Must have some GC threads");
299
300 // Root scanning phases
301 _gc_par_phases[ShenandoahPhaseTimings::ThreadRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
302 _gc_par_phases[ShenandoahPhaseTimings::CodeCacheRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms):");
303 _gc_par_phases[ShenandoahPhaseTimings::StringTableRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
304 _gc_par_phases[ShenandoahPhaseTimings::UniverseRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
305 _gc_par_phases[ShenandoahPhaseTimings::JNIRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
306 _gc_par_phases[ShenandoahPhaseTimings::JNIWeakRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JNI Weak Roots (ms):");
307 _gc_par_phases[ShenandoahPhaseTimings::ObjectSynchronizerRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
308 _gc_par_phases[ShenandoahPhaseTimings::FlatProfilerRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):");
309 _gc_par_phases[ShenandoahPhaseTimings::ManagementRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
310 _gc_par_phases[ShenandoahPhaseTimings::SystemDictionaryRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
311 _gc_par_phases[ShenandoahPhaseTimings::CLDGRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
312 _gc_par_phases[ShenandoahPhaseTimings::JVMTIRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
313 _gc_par_phases[ShenandoahPhaseTimings::FinishQueues] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Finish Queues (ms):");
314 }
315
316 // record the time a phase took in seconds
317 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) {
318 _gc_par_phases[phase]->set(worker_i, secs);
319 }
320
321 double ShenandoahWorkerTimings::average(uint i) {
322 return _gc_par_phases[i]->average();
323 }
324 void ShenandoahWorkerTimings::reset(uint i) {
325 _gc_par_phases[i]->reset();
326 }
327
328 void ShenandoahWorkerTimings::print() {
329 for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) {
330 _gc_par_phases[i]->print_summary_on(tty);
331 }
332 }
333
334 ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahWorkerTimings* worker_times,
335 ShenandoahPhaseTimings::GCParPhases phase, uint worker_id) :
336 _worker_times(worker_times), _phase(phase), _worker_id(worker_id) {
337 if (_worker_times != NULL) {
338 _start_time = os::elapsedTime();
339 }
340 }
341
342 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() {
343 if (_worker_times != NULL) {
344 _worker_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
345 }
346 }
|
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
26 #include "gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp"
27 #include "gc_implementation/shenandoah/shenandoahPhaseTimings.hpp"
28 #include "gc_implementation/shenandoah/shenandoahHeap.hpp"
29 #include "gc_implementation/shenandoah/shenandoahWorkerDataArray.hpp"
30 #include "gc_implementation/shenandoah/shenandoahHeuristics.hpp"
31 #include "utilities/ostream.hpp"
32
33 ShenandoahPhaseTimings::ShenandoahPhaseTimings() : _policy(NULL) {
34 uint max_workers = (uint)MAX2(ConcGCThreads, ParallelGCThreads);
35 _worker_times = new ShenandoahWorkerTimings(max_workers);
36 _termination_times = new ShenandoahTerminationTimings(max_workers);
37 _policy = ShenandoahHeap::heap()->shenandoahPolicy();
38 assert(_policy != NULL, "Can not be NULL");
39 init_phase_names();
40 }
41
42 void ShenandoahPhaseTimings::record_phase_start(Phase phase) {
43 _timing_data[phase]._start = os::elapsedTime();
44 }
45
46 void ShenandoahPhaseTimings::record_phase_end(Phase phase) {
47 assert(_policy != NULL, "Not yet initialized");
48 double end = os::elapsedTime();
49 double elapsed = end - _timing_data[phase]._start;
50 if (!_policy->is_at_shutdown()) {
51 _timing_data[phase]._secs.add(elapsed);
52 }
53 ShenandoahHeap::heap()->heuristics()->record_phase_time(phase, elapsed);
54 }
55
56 void ShenandoahPhaseTimings::record_phase_time(Phase phase, jint time_us) {
57 assert(_policy != NULL, "Not yet initialized");
58 if (!_policy->is_at_shutdown()) {
59 _timing_data[phase]._secs.add((double)time_us / 1000 / 1000);
60 }
61 }
62
63 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
64 for (uint i = 0; i < GCParPhasesSentinel; i++) {
65 _worker_times->reset(i);
66 }
67 }
68
69 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
70 if (_policy->is_at_shutdown()) {
71 // Do not record the past-shutdown events
72 return;
73 }
74
75 guarantee(phase == init_evac ||
76 phase == scan_roots ||
77 phase == update_roots ||
78 phase == final_update_refs_roots ||
79 phase == full_gc_roots ||
80 phase == _num_phases,
81 "only in these phases we can add per-thread phase times");
82 if (phase != _num_phases) {
83 // Merge _phase_time to counters below the given phase.
84 for (uint i = 0; i < GCParPhasesSentinel; i++) {
85 double t = _worker_times->average(i);
86 _timing_data[phase + i + 1]._secs.add(t);
87 }
88 }
89 }
90
91 void ShenandoahPhaseTimings::print_on(outputStream* out) const {
92 out->cr();
93 out->print_cr("GC STATISTICS:");
94 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
95 out->print_cr(" and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect.");
96 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code.");
97 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense.");
98 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
99 out->cr();
100
101 for (uint i = 0; i < _num_phases; i++) {
102 if (_timing_data[i]._secs.maximum() != 0) {
103 print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs));
104 }
105 }
106 }
107
108 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const {
109 out->print_cr("%-27s = %8.2lf s (a = %8.0lf us) (n = " INT32_FORMAT_W(5) ") (lvls, us = %8.0lf, %8.0lf, %8.0lf, %8.0lf, %8.0lf)",
110 str,
111 seq->sum(),
112 seq->avg() * 1000000.0,
113 seq->num(),
114 seq->percentile(0) * 1000000.0,
115 seq->percentile(25) * 1000000.0,
116 seq->percentile(50) * 1000000.0,
117 seq->percentile(75) * 1000000.0,
118 seq->maximum() * 1000000.0
119 );
120 }
121
122 void ShenandoahPhaseTimings::init_phase_names() {
123 _phase_names[total_pause] = "Total Pauses (N)";
124 _phase_names[total_pause_gross] = "Total Pauses (G)";
125 _phase_names[init_mark] = "Pause Init Mark (N)";
126 _phase_names[init_mark_gross] = "Pause Init Mark (G)";
127 _phase_names[final_mark] = "Pause Final Mark (N)";
128 _phase_names[final_mark_gross] = "Pause Final Mark (G)";
129 _phase_names[final_evac] = "Pause Final Evac (N)";
130 _phase_names[final_evac_gross] = "Pause Final Evac (G)";
131 _phase_names[accumulate_stats] = " Accumulate Stats";
132 _phase_names[make_parsable] = " Make Parsable";
133 _phase_names[clear_liveness] = " Clear Liveness";
134 _phase_names[resize_tlabs] = " Resize TLABs";
135 _phase_names[finish_queues] = " Finish Queues";
136 _phase_names[termination] = " Termination";
137 _phase_names[weakrefs] = " Weak References";
138 _phase_names[weakrefs_process] = " Process";
139 _phase_names[weakrefs_termination] = " Termination";
140 _phase_names[weakrefs_enqueue] = " Enqueue";
141 _phase_names[purge] = " System Purge";
142 _phase_names[purge_class_unload] = " Unload Classes";
143 _phase_names[purge_par] = " Parallel Cleanup";
144 _phase_names[purge_par_codecache] = " Code Cache";
145 _phase_names[purge_par_symbstring] = " String/Symbol Tables";
146 _phase_names[purge_par_rmt] = " Resolved Methods";
147 _phase_names[purge_par_classes] = " Clean Classes";
148 _phase_names[purge_par_sync] = " Synchronization";
149 _phase_names[purge_par_string_dedup] = " String Dedup";
150 _phase_names[purge_cldg] = " CLDG";
151 _phase_names[complete_liveness] = " Complete Liveness";
152 _phase_names[prepare_evac] = " Prepare Evacuation";
153
154 _phase_names[scan_roots] = " Scan Roots";
155 _phase_names[scan_thread_roots] = " S: Thread Roots";
156 _phase_names[scan_code_roots] = " S: Code Cache Roots";
157 _phase_names[scan_string_table_roots] = " S: String Table Roots";
158 _phase_names[scan_universe_roots] = " S: Universe Roots";
159 _phase_names[scan_jni_roots] = " S: JNI Roots";
160 _phase_names[scan_jni_weak_roots] = " S: JNI Weak Roots";
161 _phase_names[scan_synchronizer_roots] = " S: Synchronizer Roots";
162 _phase_names[scan_flat_profiler_roots] = " S: Flat Profiler Roots";
163 _phase_names[scan_management_roots] = " S: Management Roots";
164 _phase_names[scan_system_dictionary_roots] = " S: System Dict Roots";
165 _phase_names[scan_cldg_roots] = " S: CLDG Roots";
166 _phase_names[scan_jvmti_roots] = " S: JVMTI Roots";
167 _phase_names[scan_string_dedup_roots] = " S: String Dedup Roots";
168 _phase_names[scan_finish_queues] = " S: Finish Queues";
169
170 _phase_names[update_roots] = " Update Roots";
171 _phase_names[update_thread_roots] = " U: Thread Roots";
172 _phase_names[update_code_roots] = " U: Code Cache Roots";
173 _phase_names[update_string_table_roots] = " U: String Table Roots";
174 _phase_names[update_universe_roots] = " U: Universe Roots";
175 _phase_names[update_jni_roots] = " U: JNI Roots";
176 _phase_names[update_jni_weak_roots] = " U: JNI Weak Roots";
177 _phase_names[update_synchronizer_roots] = " U: Synchronizer Roots";
178 _phase_names[update_flat_profiler_roots] = " U: Flat Profiler Roots";
179 _phase_names[update_management_roots] = " U: Management Roots";
180 _phase_names[update_system_dictionary_roots] = " U: System Dict Roots";
181 _phase_names[update_cldg_roots] = " U: CLDG Roots";
182 _phase_names[update_jvmti_roots] = " U: JVMTI Roots";
183 _phase_names[update_string_dedup_roots] = " U: String Dedup Roots";
184 _phase_names[update_finish_queues] = " U: Finish Queues";
185
186 _phase_names[init_evac] = " Initial Evacuation";
187 _phase_names[evac_thread_roots] = " E: Thread Roots";
188 _phase_names[evac_code_roots] = " E: Code Cache Roots";
189 _phase_names[evac_string_table_roots] = " E: String Table Roots";
190 _phase_names[evac_universe_roots] = " E: Universe Roots";
191 _phase_names[evac_jni_roots] = " E: JNI Roots";
192 _phase_names[evac_jni_weak_roots] = " E: JNI Weak Roots";
193 _phase_names[evac_synchronizer_roots] = " E: Synchronizer Roots";
194 _phase_names[evac_flat_profiler_roots] = " E: Flat Profiler Roots";
195 _phase_names[evac_management_roots] = " E: Management Roots";
196 _phase_names[evac_system_dictionary_roots] = " E: System Dict Roots";
197 _phase_names[evac_cldg_roots] = " E: CLDG Roots";
198 _phase_names[evac_jvmti_roots] = " E: JVMTI Roots";
199 _phase_names[evac_string_dedup_roots] = " E: String Dedup Roots";
200 _phase_names[evac_finish_queues] = " E: Finish Queues";
201
202 _phase_names[recycle_regions] = " Recycle regions";
203
204 _phase_names[degen_gc_gross] = "Pause Degenerated GC (G)";
205 _phase_names[degen_gc] = "Pause Degenerated GC (N)";
206
207 _phase_names[full_gc_gross] = "Pause Full GC (G)";
208 _phase_names[full_gc] = "Pause Full GC (N)";
209 _phase_names[full_gc_heapdumps] = " Heap Dumps";
210 _phase_names[full_gc_prepare] = " Prepare";
211 _phase_names[full_gc_roots] = " Roots";
212 _phase_names[full_gc_thread_roots] = " F: Thread Roots";
213 _phase_names[full_gc_code_roots] = " F: Code Cache Roots";
214 _phase_names[full_gc_string_table_roots] = " F: String Table Roots";
215 _phase_names[full_gc_universe_roots] = " F: Universe Roots";
216 _phase_names[full_gc_jni_roots] = " F: JNI Roots";
217 _phase_names[full_gc_jni_weak_roots] = " F: JNI Weak Roots";
218 _phase_names[full_gc_synchronizer_roots] = " F: Synchronizer Roots";
219 _phase_names[full_gc_flat_profiler_roots] = " F: Flat Profiler Roots";
220 _phase_names[full_gc_management_roots] = " F: Management Roots";
221 _phase_names[full_gc_system_dictionary_roots] = " F: System Dict Roots";
222 _phase_names[full_gc_cldg_roots] = " F: CLDG Roots";
223 _phase_names[full_gc_jvmti_roots] = " F: JVMTI Roots";
224 _phase_names[full_gc_string_dedup_roots] = " F: String Dedup Roots";
225 _phase_names[full_gc_finish_queues] = " F: Finish Queues";
226 _phase_names[full_gc_mark] = " Mark";
227 _phase_names[full_gc_mark_finish_queues] = " Finish Queues";
228 _phase_names[full_gc_mark_termination] = " Termination";
229 _phase_names[full_gc_weakrefs] = " Weak References";
230 _phase_names[full_gc_weakrefs_process] = " Process";
231 _phase_names[full_gc_weakrefs_termination] = " Termination";
232 _phase_names[full_gc_weakrefs_enqueue] = " Enqueue";
233 _phase_names[full_gc_purge] = " System Purge";
234 _phase_names[full_gc_purge_class_unload] = " Unload Classes";
235 _phase_names[full_gc_purge_par] = " Parallel Cleanup";
236 _phase_names[full_gc_purge_par_codecache] = " Code Cache";
237 _phase_names[full_gc_purge_par_symbstring] = " String/Symbol Tables";
238 _phase_names[full_gc_purge_par_rmt] = " Resolved Methods";
239 _phase_names[full_gc_purge_par_classes] = " Clean Classes";
240 _phase_names[full_gc_purge_par_sync] = " Synchronization";
241 _phase_names[full_gc_purge_cldg] = " CLDG";
242 _phase_names[full_gc_purge_par_string_dedup] = " Purge String Dedup";
243 _phase_names[full_gc_calculate_addresses] = " Calculate Addresses";
244 _phase_names[full_gc_calculate_addresses_regular] = " Regular Objects";
245 _phase_names[full_gc_calculate_addresses_humong] = " Humongous Objects";
246 _phase_names[full_gc_adjust_pointers] = " Adjust Pointers";
247 _phase_names[full_gc_copy_objects] = " Copy Objects";
248 _phase_names[full_gc_copy_objects_regular] = " Regular Objects";
249 _phase_names[full_gc_copy_objects_humong] = " Humongous Objects";
250 _phase_names[full_gc_copy_objects_reset_next] = " Reset Next Bitmap";
251 _phase_names[full_gc_copy_objects_reset_complete] = " Reset Complete Bitmap";
252 _phase_names[full_gc_copy_objects_rebuild] = " Rebuild Region Sets";
253 _phase_names[full_gc_update_str_dedup_table] = " Update String Dedup Table";
254 _phase_names[full_gc_resize_tlabs] = " Resize TLABs";
255
256 _phase_names[pause_other] = "Pause Other";
257
258 _phase_names[conc_mark] = "Concurrent Marking";
259 _phase_names[conc_termination] = " Termination";
260 _phase_names[conc_preclean] = "Concurrent Precleaning";
261 _phase_names[conc_evac] = "Concurrent Evacuation";
262 _phase_names[conc_cleanup] = "Concurrent Cleanup";
263 _phase_names[conc_cleanup_recycle] = " Recycle";
264 _phase_names[conc_cleanup_reset_bitmaps] = " Reset Bitmaps";
265 _phase_names[conc_other] = "Concurrent Other";
266
267 _phase_names[conc_uncommit] = "Concurrent Uncommit";
268
269 _phase_names[init_update_refs_gross] = "Pause Init Update Refs (G)";
270 _phase_names[init_update_refs] = "Pause Init Update Refs (N)";
271 _phase_names[conc_update_refs] = "Concurrent Update Refs";
272 _phase_names[final_update_refs_gross] = "Pause Final Update Refs (G)";
273 _phase_names[final_update_refs] = "Pause Final Update Refs (N)";
274
275 _phase_names[final_update_refs_finish_work] = " Finish Work";
276 _phase_names[final_update_refs_roots] = " Update Roots";
277 _phase_names[final_update_refs_thread_roots] = " UR: Thread Roots";
278 _phase_names[final_update_refs_code_roots] = " UR: Code Cache Roots";
279 _phase_names[final_update_refs_string_table_roots] = " UR: String Table Roots";
280 _phase_names[final_update_refs_universe_roots] = " UR: Universe Roots";
281 _phase_names[final_update_refs_jni_roots] = " UR: JNI Roots";
282 _phase_names[final_update_refs_jni_weak_roots] = " UR: JNI Weak Roots";
283 _phase_names[final_update_refs_synchronizer_roots] = " UR: Synchronizer Roots";
284 _phase_names[final_update_refs_flat_profiler_roots] = " UR: Flat Profiler Roots";
285 _phase_names[final_update_refs_management_roots] = " UR: Management Roots";
286 _phase_names[final_update_refs_system_dict_roots] = " UR: System Dict Roots";
287 _phase_names[final_update_refs_cldg_roots] = " UR: CLDG Roots";
288 _phase_names[final_update_refs_jvmti_roots] = " UR: JVMTI Roots";
289 _phase_names[final_update_refs_string_dedup_roots] = " UR: String Dedup Roots";
290 _phase_names[final_update_refs_finish_queues] = " UR: Finish Queues";
291 _phase_names[final_update_refs_recycle] = " Recycle";
292 }
293
294 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) :
295 _max_gc_threads(max_gc_threads)
296 {
297 assert(max_gc_threads > 0, "Must have some GC threads");
298
299 // Root scanning phases
300 _gc_par_phases[ShenandoahPhaseTimings::ThreadRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
301 _gc_par_phases[ShenandoahPhaseTimings::CodeCacheRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms):");
302 _gc_par_phases[ShenandoahPhaseTimings::StringTableRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
303 _gc_par_phases[ShenandoahPhaseTimings::UniverseRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
304 _gc_par_phases[ShenandoahPhaseTimings::JNIRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
305 _gc_par_phases[ShenandoahPhaseTimings::JNIWeakRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JNI Weak Roots (ms):");
306 _gc_par_phases[ShenandoahPhaseTimings::ObjectSynchronizerRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
307 _gc_par_phases[ShenandoahPhaseTimings::FlatProfilerRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):");
308 _gc_par_phases[ShenandoahPhaseTimings::ManagementRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
309 _gc_par_phases[ShenandoahPhaseTimings::SystemDictionaryRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
310 _gc_par_phases[ShenandoahPhaseTimings::CLDGRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
311 _gc_par_phases[ShenandoahPhaseTimings::JVMTIRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
312 _gc_par_phases[ShenandoahPhaseTimings::StringDedupRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "String Dedup Roots (ms):");
313 _gc_par_phases[ShenandoahPhaseTimings::FinishQueues] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Finish Queues (ms):");
314 }
315
316 // record the time a phase took in seconds
317 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) {
318 _gc_par_phases[phase]->set(worker_i, secs);
319 }
320
321 double ShenandoahWorkerTimings::average(uint i) {
322 return _gc_par_phases[i]->average();
323 }
324 void ShenandoahWorkerTimings::reset(uint i) {
325 _gc_par_phases[i]->reset();
326 }
327
328 void ShenandoahWorkerTimings::print() {
329 for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) {
330 _gc_par_phases[i]->print_summary_on(tty);
331 }
332 }
333
334 ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahWorkerTimings* worker_times,
335 ShenandoahPhaseTimings::GCParPhases phase, uint worker_id) :
336 _phase(phase), _worker_times(worker_times), _worker_id(worker_id) {
337 if (_worker_times != NULL) {
338 _start_time = os::elapsedTime();
339 }
340 }
341
342 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() {
343 if (_worker_times != NULL) {
344 _worker_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
345 }
346 }
347
348 ShenandoahTerminationTimings::ShenandoahTerminationTimings(uint max_gc_threads) {
349 _gc_termination_phase = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Task Termination (ms):");
350 }
351
352 void ShenandoahTerminationTimings::record_time_secs(uint worker_id, double secs) {
353 if (_gc_termination_phase->get(worker_id) == ShenandoahWorkerDataArray<double>::uninitialized()) {
354 _gc_termination_phase->set(worker_id, secs);
355 } else {
356 // worker may re-enter termination phase
357 _gc_termination_phase->add(worker_id, secs);
358 }
359 }
360
361 void ShenandoahTerminationTimings::print() const {
362 _gc_termination_phase->print_summary_on(tty);
363 }
364
365 ShenandoahTerminationTimingsTracker::ShenandoahTerminationTimingsTracker(uint worker_id) :
366 _worker_id(worker_id) {
367 if (ShenandoahTerminationTrace) {
368 _start_time = os::elapsedTime();
369 }
370 }
371
372 ShenandoahTerminationTimingsTracker::~ShenandoahTerminationTimingsTracker() {
373 if (ShenandoahTerminationTrace) {
374 ShenandoahHeap::heap()->phase_timings()->termination_times()->record_time_secs(_worker_id, os::elapsedTime() - _start_time);
375 }
376 }
377
378 ShenandoahPhaseTimings::Phase ShenandoahTerminationTracker::currentPhase = ShenandoahPhaseTimings::_num_phases;
379
380 ShenandoahTerminationTracker::ShenandoahTerminationTracker(ShenandoahPhaseTimings::Phase phase) : _phase(phase) {
381 assert(currentPhase == ShenandoahPhaseTimings::_num_phases, "Should be invalid");
382 assert(phase == ShenandoahPhaseTimings::termination ||
383 phase == ShenandoahPhaseTimings::full_gc_mark_termination ||
384 phase == ShenandoahPhaseTimings::conc_termination ||
385 phase == ShenandoahPhaseTimings::weakrefs_termination ||
386 phase == ShenandoahPhaseTimings::full_gc_weakrefs_termination,
387 "Only these phases");
388
389 assert(Thread::current()->is_VM_thread() || Thread::current()->is_ConcurrentGC_thread(),
390 "Called from wrong thread");
391
392 currentPhase = phase;
393 ShenandoahHeap::heap()->phase_timings()->termination_times()->reset();
394 }
395
396 ShenandoahTerminationTracker::~ShenandoahTerminationTracker() {
397 assert(_phase == currentPhase, "Can not change phase");
398 ShenandoahPhaseTimings* phase_times = ShenandoahHeap::heap()->phase_timings();
399
400 double t = phase_times->termination_times()->average();
401 phase_times->record_phase_time(_phase, t * 1000 * 1000);
402 debug_only(currentPhase = ShenandoahPhaseTimings::_num_phases;)
403 }
|