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/g1CollectedHeap.inline.hpp"
27 #include "gc/g1/g1GCPhaseTimes.hpp"
28 #include "gc/g1/g1HotCardCache.hpp"
29 #include "gc/g1/g1ParScanThreadState.inline.hpp"
30 #include "gc/g1/g1StringDedup.hpp"
31 #include "gc/shared/gcTimer.hpp"
32 #include "gc/shared/workerDataArray.inline.hpp"
33 #include "memory/resourceArea.hpp"
34 #include "logging/log.hpp"
35 #include "logging/logStream.hpp"
36 #include "runtime/timer.hpp"
37 #include "runtime/os.hpp"
38 #include "utilities/macros.hpp"
39
40 static const char* Indents[5] = {"", " ", " ", " ", " "};
41
42 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
43 _max_gc_threads(max_gc_threads),
44 _gc_start_counter(0),
45 _gc_pause_time_ms(0.0),
46 _ref_phase_times(gc_timer, max_gc_threads),
47 _weak_phase_times(max_gc_threads)
48 {
49 assert(max_gc_threads > 0, "Must have some GC threads");
50
51 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>("GC Worker Start (ms):", max_gc_threads);
52 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>("Ext Root Scanning (ms):", max_gc_threads);
53
54 // Root scanning phases
55 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>("Thread Roots (ms):", max_gc_threads);
56 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>("Universe Roots (ms):", max_gc_threads);
57 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>("JNI Handles Roots (ms):", max_gc_threads);
58 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>("ObjectSynchronizer Roots (ms):", max_gc_threads);
59 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>("Management Roots (ms):", max_gc_threads);
60 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>("SystemDictionary Roots (ms):", max_gc_threads);
292
293 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
294 if (_gc_par_phases[phase] == NULL) {
295 return 0;
296 }
297 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
298 return _gc_par_phases[phase]->thread_work_items(index)->sum();
299 }
300
301 template <class T>
302 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
303 LogTarget(Trace, gc, phases, task) lt;
304 if (lt.is_enabled()) {
305 LogStream ls(lt);
306 ls.print("%s", indent);
307 phase->print_details_on(&ls);
308 }
309 }
310
311 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
312 out->print("%s", Indents[indent]);
313 phase->print_summary_on(out, print_sum);
314 details(phase, Indents[indent]);
315
316 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
317 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
318 if (work_items != NULL) {
319 out->print("%s", Indents[indent + 1]);
320 work_items->print_summary_on(out, true);
321 details(work_items, Indents[indent + 1]);
322 }
323 }
324 }
325
326 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const {
327 LogTarget(Debug, gc, phases) lt;
328 if (lt.is_enabled()) {
329 ResourceMark rm;
330 LogStream ls(lt);
331 log_phase(phase, 2 + extra_indent, &ls, true);
332 }
333 }
334
335 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum, uint extra_indent) const {
336 LogTarget(Trace, gc, phases) lt;
337 if (lt.is_enabled()) {
338 LogStream ls(lt);
339 log_phase(phase, 3 + extra_indent, &ls, print_sum);
340 }
341 }
342
343 #define TIME_FORMAT "%.1lfms"
344
345 void G1GCPhaseTimes::info_time(const char* name, double value) const {
346 log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
347 }
348
349 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
350 log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
351 }
352
353 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
354 LogTarget(Debug, gc, phases) lt;
355 LogTarget(Debug, gc, phases, ref) lt2;
356
357 if (lt.is_enabled()) {
358 LogStream ls(lt);
359 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
360 } else if (lt2.is_enabled()) {
361 LogStream ls(lt2);
362 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
363 }
364 }
365
366 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
367 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
368 }
369
370 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
371 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
372 }
373
374 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
375 const double sum_ms = _root_region_scan_wait_time_ms +
376 _recorded_young_cset_choice_time_ms +
377 _recorded_non_young_cset_choice_time_ms +
378 _cur_region_register_time +
379 _recorded_prepare_heap_roots_time_ms +
380 _recorded_clear_claimed_marks_time_ms;
381
382 info_time("Pre Evacuate Collection Set", sum_ms);
383
384 if (_root_region_scan_wait_time_ms > 0.0) {
385 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
386 }
387 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
388 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
389 debug_time("Region Register", _cur_region_register_time);
390 if (G1EagerReclaimHumongousObjects) {
391 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
|
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/g1CollectedHeap.inline.hpp"
27 #include "gc/g1/g1GCPhaseTimes.hpp"
28 #include "gc/g1/g1HotCardCache.hpp"
29 #include "gc/g1/g1ParScanThreadState.inline.hpp"
30 #include "gc/g1/g1StringDedup.hpp"
31 #include "gc/shared/gcTimer.hpp"
32 #include "gc/shared/workerDataArray.inline.hpp"
33 #include "memory/resourceArea.hpp"
34 #include "logging/log.hpp"
35 #include "logging/logStream.hpp"
36 #include "runtime/timer.hpp"
37 #include "runtime/os.hpp"
38 #include "utilities/macros.hpp"
39
40 static void generate_indent(int num_indent, char* buf, size_t buflen){
41 if (num_indent <= 0) {
42 *buf = '\0';
43 } else {
44 jio_snprintf(buf, buflen, "%*c", num_indent * 2, ' ');
45 }
46 }
47
48 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
49 _max_gc_threads(max_gc_threads),
50 _gc_start_counter(0),
51 _gc_pause_time_ms(0.0),
52 _ref_phase_times(gc_timer, max_gc_threads),
53 _weak_phase_times(max_gc_threads)
54 {
55 assert(max_gc_threads > 0, "Must have some GC threads");
56
57 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>("GC Worker Start (ms):", max_gc_threads);
58 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>("Ext Root Scanning (ms):", max_gc_threads);
59
60 // Root scanning phases
61 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>("Thread Roots (ms):", max_gc_threads);
62 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>("Universe Roots (ms):", max_gc_threads);
63 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>("JNI Handles Roots (ms):", max_gc_threads);
64 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>("ObjectSynchronizer Roots (ms):", max_gc_threads);
65 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>("Management Roots (ms):", max_gc_threads);
66 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>("SystemDictionary Roots (ms):", max_gc_threads);
298
299 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
300 if (_gc_par_phases[phase] == NULL) {
301 return 0;
302 }
303 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
304 return _gc_par_phases[phase]->thread_work_items(index)->sum();
305 }
306
307 template <class T>
308 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
309 LogTarget(Trace, gc, phases, task) lt;
310 if (lt.is_enabled()) {
311 LogStream ls(lt);
312 ls.print("%s", indent);
313 phase->print_details_on(&ls);
314 }
315 }
316
317 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
318 char buf[O_BUFLEN];
319 generate_indent(indent, buf, O_BUFLEN);
320 out->print("%s", buf);
321 phase->print_summary_on(out, print_sum);
322 details(phase, buf);
323
324 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
325 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
326 if (work_items != NULL) {
327 generate_indent(indent + 1, buf, O_BUFLEN);
328 out->print("%s", buf);
329 work_items->print_summary_on(out, true);
330 details(work_items, buf);
331 }
332 }
333 }
334
335 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const {
336 LogTarget(Debug, gc, phases) lt;
337 if (lt.is_enabled()) {
338 ResourceMark rm;
339 LogStream ls(lt);
340 log_phase(phase, 2 + extra_indent, &ls, true);
341 }
342 }
343
344 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum, uint extra_indent) const {
345 LogTarget(Trace, gc, phases) lt;
346 if (lt.is_enabled()) {
347 LogStream ls(lt);
348 log_phase(phase, 3 + extra_indent, &ls, print_sum);
349 }
350 }
351
352 #define TIME_FORMAT "%.1lfms"
353
354 void G1GCPhaseTimes::info_time(const char* name, double value) const {
355 char buf[O_BUFLEN];
356 generate_indent(1, buf, O_BUFLEN);
357 log_info(gc, phases)("%s%s: " TIME_FORMAT, buf, name, value);
358 }
359
360 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
361 char buf[O_BUFLEN];
362 generate_indent(2, buf, O_BUFLEN);
363 log_debug(gc, phases)("%s%s: " TIME_FORMAT, buf, name, value);
364 }
365
366 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
367 char buf[O_BUFLEN];
368 generate_indent(2, buf, O_BUFLEN);
369
370 LogTarget(Debug, gc, phases) lt;
371 LogTarget(Debug, gc, phases, ref) lt2;
372
373 if (lt.is_enabled()) {
374 LogStream ls(lt);
375 ls.print_cr("%s%s: " TIME_FORMAT, buf, name, value);
376 } else if (lt2.is_enabled()) {
377 LogStream ls(lt2);
378 ls.print_cr("%s%s: " TIME_FORMAT, buf, name, value);
379 }
380 }
381
382 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
383 char buf[O_BUFLEN];
384 generate_indent(3, buf, O_BUFLEN);
385 log_trace(gc, phases)("%s%s: " TIME_FORMAT, buf, name, value);
386 }
387
388 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
389 char buf[O_BUFLEN];
390 generate_indent(3, buf, O_BUFLEN);
391 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, buf, name, value);
392 }
393
394 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
395 const double sum_ms = _root_region_scan_wait_time_ms +
396 _recorded_young_cset_choice_time_ms +
397 _recorded_non_young_cset_choice_time_ms +
398 _cur_region_register_time +
399 _recorded_prepare_heap_roots_time_ms +
400 _recorded_clear_claimed_marks_time_ms;
401
402 info_time("Pre Evacuate Collection Set", sum_ms);
403
404 if (_root_region_scan_wait_time_ms > 0.0) {
405 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
406 }
407 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
408 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
409 debug_time("Region Register", _cur_region_register_time);
410 if (G1EagerReclaimHumongousObjects) {
411 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
|