13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25 #include "precompiled.hpp"
26 #include "gc/g1/concurrentG1Refine.hpp"
27 #include "gc/g1/g1CollectedHeap.inline.hpp"
28 #include "gc/g1/g1GCPhaseTimes.hpp"
29 #include "gc/g1/g1StringDedup.hpp"
30 #include "gc/g1/workerDataArray.inline.hpp"
31 #include "memory/allocation.hpp"
32 #include "logging/log.hpp"
33 #include "runtime/os.hpp"
34
35 // Helper class for avoiding interleaved logging
36 class LineBuffer: public StackObj {
37
38 private:
39 static const int BUFFER_LEN = 1024;
40 static const int INDENT_CHARS = 3;
41 char _buffer[BUFFER_LEN];
42 int _indent_level;
43 int _cur;
44
45 void vappend(const char* format, va_list ap) ATTRIBUTE_PRINTF(2, 0) {
46 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
47 if (res != -1) {
48 _cur += res;
49 } else {
50 DEBUG_ONLY(warning("buffer too small in LineBuffer");)
51 _buffer[BUFFER_LEN -1] = 0;
52 _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
116 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End:", false, 2);
117 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other:", true, 2);
118
119 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:", true, 3);
120 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
121
122 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:", true, 3);
123 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
124
125 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup:", true, 2);
126 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup:", true, 2);
127
128 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, 3);
129 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:", true, 3);
130 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
131 }
132
133 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
134 assert(active_gc_threads > 0, "The number of threads must be > 0");
135 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
136 _active_gc_threads = active_gc_threads;
137 _cur_expand_heap_time_ms = 0.0;
138 _external_accounted_time_ms = 0.0;
139
140 for (int i = 0; i < GCParPhasesSentinel; i++) {
141 _gc_par_phases[i]->reset();
142 }
143
144 _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
145 _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
146 }
147
148 void G1GCPhaseTimes::note_gc_end() {
149 for (uint i = 0; i < _active_gc_threads; i++) {
150 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
151 record_time_secs(GCWorkerTotal, i , worker_time);
152
153 double worker_known_time =
154 _gc_par_phases[ExtRootScan]->get(i) +
155 _gc_par_phases[SATBFiltering]->get(i) +
156 _gc_par_phases[UpdateRS]->get(i) +
157 _gc_par_phases[ScanRS]->get(i) +
158 _gc_par_phases[CodeRoots]->get(i) +
159 _gc_par_phases[ObjCopy]->get(i) +
160 _gc_par_phases[Termination]->get(i);
161
162 record_time_secs(Other, i, worker_time - worker_known_time);
163 }
164
165 for (int i = 0; i < GCParPhasesSentinel; i++) {
166 _gc_par_phases[i]->verify(_active_gc_threads);
167 }
168 }
332 if (phase->_print_sum) {
333 log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
334 indent, phase->_title,
335 _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
336 _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id), _phase_times->sum_time_ms(phase_id));
337 } else {
338 log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf",
339 indent, phase->_title,
340 _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
341 _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
342 }
343
344 print_time_values(indent, phase_id);
345
346 if (phase->_thread_work_items != NULL) {
347 print_thread_work_items(phase_id, phase->_thread_work_items);
348 }
349 }
350 };
351
352 void G1GCPhaseTimes::print(double pause_time_ms) {
353 note_gc_end();
354
355 G1GCParPhasePrinter par_phase_printer(this);
356
357 if (_root_region_scan_wait_time_ms > 0.0) {
358 print_stats(Indents[1], "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
359 }
360
361 print_stats(Indents[1], "Parallel Time", _cur_collection_par_time_ms);
362 for (int i = 0; i <= GCMainParPhasesLast; i++) {
363 par_phase_printer.print((GCParPhases) i);
364 }
365
366 print_stats(Indents[1], "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
367 print_stats(Indents[1], "Code Root Purge", _cur_strong_code_root_purge_time_ms);
368 if (G1StringDedup::is_enabled()) {
369 print_stats(Indents[1], "String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
370 for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
371 par_phase_printer.print((GCParPhases) i);
372 }
373 }
374 print_stats(Indents[1], "Clear CT", _cur_clear_ct_time_ms);
375 print_stats(Indents[1], "Expand Heap After Collection", _cur_expand_heap_time_ms);
376 double misc_time_ms = pause_time_ms - accounted_time_ms();
377 print_stats(Indents[1], "Other", misc_time_ms);
378 if (_cur_verify_before_time_ms > 0.0) {
379 print_stats(Indents[2], "Verify Before", _cur_verify_before_time_ms);
380 }
381 if (G1CollectedHeap::heap()->evacuation_failed()) {
382 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
383 _cur_evac_fail_restore_remsets;
384 print_stats(Indents[2], "Evacuation Failure", evac_fail_handling);
385 log_trace(gc, phases)("%sRecalculate Used: %.1lf ms", Indents[3], _cur_evac_fail_recalc_used);
386 log_trace(gc, phases)("%sRemove Self Forwards: %.1lf ms", Indents[3], _cur_evac_fail_remove_self_forwards);
387 log_trace(gc, phases)("%sRestore RemSet: %.1lf ms", Indents[3], _cur_evac_fail_restore_remsets);
388 }
389 print_stats(Indents[2], "Choose CSet",
390 (_recorded_young_cset_choice_time_ms +
391 _recorded_non_young_cset_choice_time_ms));
392 print_stats(Indents[2], "Ref Proc", _cur_ref_proc_time_ms);
393 print_stats(Indents[2], "Ref Enq", _cur_ref_enq_time_ms);
394 print_stats(Indents[2], "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
395 par_phase_printer.print(RedirtyCards);
396 if (G1EagerReclaimHumongousObjects) {
|
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25 #include "precompiled.hpp"
26 #include "gc/g1/concurrentG1Refine.hpp"
27 #include "gc/g1/g1CollectedHeap.inline.hpp"
28 #include "gc/g1/g1GCPhaseTimes.hpp"
29 #include "gc/g1/g1StringDedup.hpp"
30 #include "gc/g1/workerDataArray.inline.hpp"
31 #include "memory/allocation.hpp"
32 #include "logging/log.hpp"
33 #include "runtime/timer.hpp"
34 #include "runtime/os.hpp"
35
36 // Helper class for avoiding interleaved logging
37 class LineBuffer: public StackObj {
38
39 private:
40 static const int BUFFER_LEN = 1024;
41 static const int INDENT_CHARS = 3;
42 char _buffer[BUFFER_LEN];
43 int _indent_level;
44 int _cur;
45
46 void vappend(const char* format, va_list ap) ATTRIBUTE_PRINTF(2, 0) {
47 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
48 if (res != -1) {
49 _cur += res;
50 } else {
51 DEBUG_ONLY(warning("buffer too small in LineBuffer");)
52 _buffer[BUFFER_LEN -1] = 0;
53 _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
117 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End:", false, 2);
118 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other:", true, 2);
119
120 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:", true, 3);
121 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
122
123 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:", true, 3);
124 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
125
126 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup:", true, 2);
127 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup:", true, 2);
128
129 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, 3);
130 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:", true, 3);
131 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
132 }
133
134 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
135 assert(active_gc_threads > 0, "The number of threads must be > 0");
136 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
137 _gc_start_counter = os::elapsed_counter();
138 _active_gc_threads = active_gc_threads;
139 _cur_expand_heap_time_ms = 0.0;
140 _external_accounted_time_ms = 0.0;
141
142 for (int i = 0; i < GCParPhasesSentinel; i++) {
143 _gc_par_phases[i]->reset();
144 }
145
146 _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
147 _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
148 }
149
150 void G1GCPhaseTimes::note_gc_end() {
151 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
152 for (uint i = 0; i < _active_gc_threads; i++) {
153 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
154 record_time_secs(GCWorkerTotal, i , worker_time);
155
156 double worker_known_time =
157 _gc_par_phases[ExtRootScan]->get(i) +
158 _gc_par_phases[SATBFiltering]->get(i) +
159 _gc_par_phases[UpdateRS]->get(i) +
160 _gc_par_phases[ScanRS]->get(i) +
161 _gc_par_phases[CodeRoots]->get(i) +
162 _gc_par_phases[ObjCopy]->get(i) +
163 _gc_par_phases[Termination]->get(i);
164
165 record_time_secs(Other, i, worker_time - worker_known_time);
166 }
167
168 for (int i = 0; i < GCParPhasesSentinel; i++) {
169 _gc_par_phases[i]->verify(_active_gc_threads);
170 }
171 }
335 if (phase->_print_sum) {
336 log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
337 indent, phase->_title,
338 _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
339 _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id), _phase_times->sum_time_ms(phase_id));
340 } else {
341 log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf",
342 indent, phase->_title,
343 _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
344 _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
345 }
346
347 print_time_values(indent, phase_id);
348
349 if (phase->_thread_work_items != NULL) {
350 print_thread_work_items(phase_id, phase->_thread_work_items);
351 }
352 }
353 };
354
355 void G1GCPhaseTimes::print() {
356 note_gc_end();
357
358 G1GCParPhasePrinter par_phase_printer(this);
359
360 if (_root_region_scan_wait_time_ms > 0.0) {
361 print_stats(Indents[1], "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
362 }
363
364 print_stats(Indents[1], "Parallel Time", _cur_collection_par_time_ms);
365 for (int i = 0; i <= GCMainParPhasesLast; i++) {
366 par_phase_printer.print((GCParPhases) i);
367 }
368
369 print_stats(Indents[1], "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
370 print_stats(Indents[1], "Code Root Purge", _cur_strong_code_root_purge_time_ms);
371 if (G1StringDedup::is_enabled()) {
372 print_stats(Indents[1], "String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
373 for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
374 par_phase_printer.print((GCParPhases) i);
375 }
376 }
377 print_stats(Indents[1], "Clear CT", _cur_clear_ct_time_ms);
378 print_stats(Indents[1], "Expand Heap After Collection", _cur_expand_heap_time_ms);
379 double misc_time_ms = _gc_pause_time_ms - accounted_time_ms();
380 print_stats(Indents[1], "Other", misc_time_ms);
381 if (_cur_verify_before_time_ms > 0.0) {
382 print_stats(Indents[2], "Verify Before", _cur_verify_before_time_ms);
383 }
384 if (G1CollectedHeap::heap()->evacuation_failed()) {
385 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
386 _cur_evac_fail_restore_remsets;
387 print_stats(Indents[2], "Evacuation Failure", evac_fail_handling);
388 log_trace(gc, phases)("%sRecalculate Used: %.1lf ms", Indents[3], _cur_evac_fail_recalc_used);
389 log_trace(gc, phases)("%sRemove Self Forwards: %.1lf ms", Indents[3], _cur_evac_fail_remove_self_forwards);
390 log_trace(gc, phases)("%sRestore RemSet: %.1lf ms", Indents[3], _cur_evac_fail_restore_remsets);
391 }
392 print_stats(Indents[2], "Choose CSet",
393 (_recorded_young_cset_choice_time_ms +
394 _recorded_non_young_cset_choice_time_ms));
395 print_stats(Indents[2], "Ref Proc", _cur_ref_proc_time_ms);
396 print_stats(Indents[2], "Ref Enq", _cur_ref_enq_time_ms);
397 print_stats(Indents[2], "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
398 par_phase_printer.print(RedirtyCards);
399 if (G1EagerReclaimHumongousObjects) {
|