Mercurial > hg > truffle

comparison src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp @ 18041:52b4284cb496

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
Merge with jdk8u20-b26
author Gilles Duboscq <duboscq@ssw.jku.at>
date Wed, 15 Oct 2014 16:02:50 +0200
parents 78bbf4d43a14
children 570cb6369f17
comparison
equal deleted inserted replaced
17606:45d7b2c7029d 18041:52b4284cb496
1 /* 1 /*
2 * Copyright (c) 2013, Oracle and/or its affiliates. All rights reserved. 2 * Copyright (c) 2013, 2014 Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 * 4 *
5 * This code is free software; you can redistribute it and/or modify it 5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as 6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation. 7 * published by the Free Software Foundation.
25 25
26 #include "precompiled.hpp" 26 #include "precompiled.hpp"
27 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" 27 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
28 #include "gc_implementation/g1/g1GCPhaseTimes.hpp" 28 #include "gc_implementation/g1/g1GCPhaseTimes.hpp"
29 #include "gc_implementation/g1/g1Log.hpp" 29 #include "gc_implementation/g1/g1Log.hpp"
30 #include "gc_implementation/g1/g1StringDedup.hpp"
30 31
31 // Helper class for avoiding interleaved logging 32 // Helper class for avoiding interleaved logging
32 class LineBuffer: public StackObj { 33 class LineBuffer: public StackObj {
33 34
34 private: 35 private:
36 static const int INDENT_CHARS = 3; 37 static const int INDENT_CHARS = 3;
37 char _buffer[BUFFER_LEN]; 38 char _buffer[BUFFER_LEN];
38 int _indent_level; 39 int _indent_level;
39 int _cur; 40 int _cur;
40 41
41 void vappend(const char* format, va_list ap) { 42 void vappend(const char* format, va_list ap) ATTRIBUTE_PRINTF(2, 0) {
42 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap); 43 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
43 if (res != -1) { 44 if (res != -1) {
44 _cur += res; 45 _cur += res;
45 } else { 46 } else {
46 DEBUG_ONLY(warning("buffer too small in LineBuffer");) 47 DEBUG_ONLY(warning("buffer too small in LineBuffer");)
60 ~LineBuffer() { 61 ~LineBuffer() {
61 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?"); 62 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
62 } 63 }
63 #endif 64 #endif
64 65
65 void append(const char* format, ...) { 66 void append(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
66 va_list ap; 67 va_list ap;
67 va_start(ap, format); 68 va_start(ap, format);
68 vappend(format, ap); 69 vappend(format, ap);
69 va_end(ap); 70 va_end(ap);
70 } 71 }
71 72
72 void append_and_print_cr(const char* format, ...) { 73 void append_and_print_cr(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
73 va_list ap; 74 va_list ap;
74 va_start(ap, format); 75 va_start(ap, format);
75 vappend(format, ap); 76 vappend(format, ap);
76 va_end(ap); 77 va_end(ap);
77 gclog_or_tty->print_cr("%s", _buffer); 78 gclog_or_tty->print_cr("%s", _buffer);
78 _cur = _indent_level * INDENT_CHARS; 79 _cur = _indent_level * INDENT_CHARS;
79 } 80 }
80 }; 81 };
81 82
83 PRAGMA_DIAG_PUSH
84 PRAGMA_FORMAT_NONLITERAL_IGNORED
82 template <class T> 85 template <class T>
83 void WorkerDataArray<T>::print(int level, const char* title) { 86 void WorkerDataArray<T>::print(int level, const char* title) {
84 if (_length == 1) { 87 if (_length == 1) {
85 // No need for min, max, average and sum for only one worker 88 // No need for min, max, average and sum for only one worker
86 LineBuffer buf(level); 89 LineBuffer buf(level);
106 buf.append(_print_format, val); 109 buf.append(_print_format, val);
107 } 110 }
108 } 111 }
109 112
110 if (G1Log::finest()) { 113 if (G1Log::finest()) {
111 buf.append_and_print_cr(""); 114 buf.append_and_print_cr("%s", "");
112 } 115 }
113 116
114 double avg = (double)sum / (double)_length; 117 double avg = (double)sum / (double)_length;
115 buf.append(" Min: "); 118 buf.append(" Min: ");
116 buf.append(_print_format, min); 119 buf.append(_print_format, min);
126 buf.append(", Sum: "); 129 buf.append(", Sum: ");
127 buf.append(_print_format, sum); 130 buf.append(_print_format, sum);
128 } 131 }
129 buf.append_and_print_cr("]"); 132 buf.append_and_print_cr("]");
130 } 133 }
134 PRAGMA_DIAG_POP
131 135
132 #ifndef PRODUCT 136 #ifndef PRODUCT
133 137
134 template <> const int WorkerDataArray<int>::_uninitialized = -1; 138 template <> const int WorkerDataArray<int>::_uninitialized = -1;
135 template <> const double WorkerDataArray<double>::_uninitialized = -1.0; 139 template <> const double WorkerDataArray<double>::_uninitialized = -1.0;
166 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"), 170 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
167 _last_termination_times_ms(_max_gc_threads, "%.1lf"), 171 _last_termination_times_ms(_max_gc_threads, "%.1lf"),
168 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT), 172 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
169 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false), 173 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
170 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"), 174 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
171 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf") 175 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"),
176 _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"),
177 _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf")
172 { 178 {
173 assert(max_gc_threads > 0, "Must have some GC threads"); 179 assert(max_gc_threads > 0, "Must have some GC threads");
174 } 180 }
175 181
176 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { 182 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
227 233
228 _last_gc_worker_times_ms.verify(); 234 _last_gc_worker_times_ms.verify();
229 _last_gc_worker_other_times_ms.verify(); 235 _last_gc_worker_other_times_ms.verify();
230 } 236 }
231 237
238 void G1GCPhaseTimes::note_string_dedup_fixup_start() {
239 _cur_string_dedup_queue_fixup_worker_times_ms.reset();
240 _cur_string_dedup_table_fixup_worker_times_ms.reset();
241 }
242
243 void G1GCPhaseTimes::note_string_dedup_fixup_end() {
244 _cur_string_dedup_queue_fixup_worker_times_ms.verify();
245 _cur_string_dedup_table_fixup_worker_times_ms.verify();
246 }
247
232 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) { 248 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
233 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value); 249 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
234 } 250 }
235 251
236 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int workers) { 252 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
237 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers); 253 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: " UINT32_FORMAT "]", str, value, workers);
238 } 254 }
239 255
240 double G1GCPhaseTimes::accounted_time_ms() { 256 double G1GCPhaseTimes::accounted_time_ms() {
241 // Subtract the root region scanning wait time. It's initialized to 257 // Subtract the root region scanning wait time. It's initialized to
242 // zero at the start of the pause. 258 // zero at the start of the pause.
247 // Now subtract the time taken to fix up roots in generated code 263 // Now subtract the time taken to fix up roots in generated code
248 misc_time_ms += _cur_collection_code_root_fixup_time_ms; 264 misc_time_ms += _cur_collection_code_root_fixup_time_ms;
249 265
250 // Strong code root migration time 266 // Strong code root migration time
251 misc_time_ms += _cur_strong_code_root_migration_time_ms; 267 misc_time_ms += _cur_strong_code_root_migration_time_ms;
268
269 // Strong code root purge time
270 misc_time_ms += _cur_strong_code_root_purge_time_ms;
271
272 if (G1StringDedup::is_enabled()) {
273 // String dedup fixup time
274 misc_time_ms += _cur_string_dedup_fixup_time_ms;
275 }
252 276
253 // Subtract the time taken to clean the card table from the 277 // Subtract the time taken to clean the card table from the
254 // current value of "other time" 278 // current value of "other time"
255 misc_time_ms += _cur_clear_ct_time_ms; 279 misc_time_ms += _cur_clear_ct_time_ms;
256 280
297 _last_strong_code_root_scan_times_ms.print(1, "Code Root Scanning (ms)"); 321 _last_strong_code_root_scan_times_ms.print(1, "Code Root Scanning (ms)");
298 _last_obj_copy_times_ms.print(1, "Object Copy (ms)"); 322 _last_obj_copy_times_ms.print(1, "Object Copy (ms)");
299 } 323 }
300 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); 324 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
301 print_stats(1, "Code Root Migration", _cur_strong_code_root_migration_time_ms); 325 print_stats(1, "Code Root Migration", _cur_strong_code_root_migration_time_ms);
326 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
327 if (G1StringDedup::is_enabled()) {
328 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
329 _cur_string_dedup_queue_fixup_worker_times_ms.print(2, "Queue Fixup (ms)");
330 _cur_string_dedup_table_fixup_worker_times_ms.print(2, "Table Fixup (ms)");
331 }
302 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); 332 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
303 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms(); 333 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
304 print_stats(1, "Other", misc_time_ms); 334 print_stats(1, "Other", misc_time_ms);
305 if (_cur_verify_before_time_ms > 0.0) { 335 if (_cur_verify_before_time_ms > 0.0) {
306 print_stats(2, "Verify Before", _cur_verify_before_time_ms); 336 print_stats(2, "Verify Before", _cur_verify_before_time_ms);
307 } 337 }
338 if (G1CollectedHeap::heap()->evacuation_failed()) {
339 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
340 _cur_evac_fail_restore_remsets;
341 print_stats(2, "Evacuation Failure", evac_fail_handling);
342 if (G1Log::finest()) {
343 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
344 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
345 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
346 }
347 }
308 print_stats(2, "Choose CSet", 348 print_stats(2, "Choose CSet",
309 (_recorded_young_cset_choice_time_ms + 349 (_recorded_young_cset_choice_time_ms +
310 _recorded_non_young_cset_choice_time_ms)); 350 _recorded_non_young_cset_choice_time_ms));
311 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms); 351 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
312 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms); 352 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
353 if (G1DeferredRSUpdate) {
354 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
355 }
313 print_stats(2, "Free CSet", 356 print_stats(2, "Free CSet",
314 (_recorded_young_free_cset_time_ms + 357 (_recorded_young_free_cset_time_ms +
315 _recorded_non_young_free_cset_time_ms)); 358 _recorded_non_young_free_cset_time_ms));
359 if (G1Log::finest()) {
360 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
361 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
362 }
316 if (_cur_verify_after_time_ms > 0.0) { 363 if (_cur_verify_after_time_ms > 0.0) {
317 print_stats(2, "Verify After", _cur_verify_after_time_ms); 364 print_stats(2, "Verify After", _cur_verify_after_time_ms);
318 } 365 }
319 } 366 }