Mercurial > hg > graal-compiler

comparison src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @ 6752:9646b7ff4d14

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
7198130: G1: PrintReferenceGC output comes out of order Summary: Move the first part of the GC logging, including timestamp, to the start of the GC Reviewed-by: johnc, jwilhelm
author brutisso
date Mon, 17 Sep 2012 10:33:13 +0200
parents da91efe96a93
children 8fbf05030e24
comparison
equal deleted inserted replaced
6751:2a48c84f1d04 6752:9646b7ff4d14
3661 task_queue(i)->stats.reset(); 3661 task_queue(i)->stats.reset();
3662 } 3662 }
3663 } 3663 }
3664 #endif // TASKQUEUE_STATS 3664 #endif // TASKQUEUE_STATS
3665 3665
3666 void G1CollectedHeap::log_gc_header() {
3667 if (!G1Log::fine()) {
3668 return;
3669 }
3670
3671 gclog_or_tty->date_stamp(PrintGCDateStamps);
3672 gclog_or_tty->stamp(PrintGCTimeStamps);
3673
3674 GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
3675 .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
3676 .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : "");
3677
3678 gclog_or_tty->print("[%s", (const char*)gc_cause_str);
3679 }
3680
3681 void G1CollectedHeap::log_gc_footer(double pause_time_sec) {
3682 if (!G1Log::fine()) {
3683 return;
3684 }
3685
3686 if (G1Log::finer()) {
3687 if (evacuation_failed()) {
3688 gclog_or_tty->print(" (to-space exhausted)");
3689 }
3690 gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec);
3691 g1_policy()->phase_times()->note_gc_end();
3692 g1_policy()->phase_times()->print(pause_time_sec);
3693 g1_policy()->print_detailed_heap_transition();
3694 } else {
3695 if (evacuation_failed()) {
3696 gclog_or_tty->print("--");
3697 }
3698 g1_policy()->print_heap_transition();
3699 gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec);
3700 }
3701 }
3702
3666 bool 3703 bool
3667 G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { 3704 G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
3668 assert_at_safepoint(true /* should_be_vm_thread */); 3705 assert_at_safepoint(true /* should_be_vm_thread */);
3669 guarantee(!is_gc_active(), "collection is not reentrant"); 3706 guarantee(!is_gc_active(), "collection is not reentrant");
3670 3707
3703 if (g1_policy()->during_initial_mark_pause()) { 3740 if (g1_policy()->during_initial_mark_pause()) {
3704 // We are about to start a marking cycle, so we increment the 3741 // We are about to start a marking cycle, so we increment the
3705 // full collection counter. 3742 // full collection counter.
3706 increment_old_marking_cycles_started(); 3743 increment_old_marking_cycles_started();
3707 } 3744 }
3708 // if the log level is "finer" is on, we'll print long statistics information
3709 // in the collector policy code, so let's not print this as the output
3710 // is messy if we do.
3711 gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
3712 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); 3745 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
3713 3746
3714 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? 3747 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
3715 workers()->active_workers() : 1); 3748 workers()->active_workers() : 1);
3716 double pause_start_sec = os::elapsedTime(); 3749 double pause_start_sec = os::elapsedTime();
3717 g1_policy()->phase_times()->note_gc_start(active_workers); 3750 g1_policy()->phase_times()->note_gc_start(active_workers);
3718 bool initial_mark_gc = g1_policy()->during_initial_mark_pause(); 3751 log_gc_header();
3719 3752
3720 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); 3753 TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
3721 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); 3754 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
3722 3755
3723 // If the secondary_free_list is not empty, append it to the 3756 // If the secondary_free_list is not empty, append it to the
4010 ParallelTaskTerminator::print_termination_counts(); 4043 ParallelTaskTerminator::print_termination_counts();
4011 #endif 4044 #endif
4012 4045
4013 gc_epilogue(false); 4046 gc_epilogue(false);
4014 4047
4015 if (G1Log::fine()) { 4048 log_gc_footer(os::elapsedTime() - pause_start_sec);
4016 if (PrintGCTimeStamps) {
4017 gclog_or_tty->stamp();
4018 gclog_or_tty->print(": ");
4019 }
4020
4021 GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
4022 .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
4023 .append(initial_mark_gc ? " (initial-mark)" : "");
4024
4025 double pause_time_sec = os::elapsedTime() - pause_start_sec;
4026
4027 if (G1Log::finer()) {
4028 if (evacuation_failed()) {
4029 gc_cause_str.append(" (to-space exhausted)");
4030 }
4031 gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_sec);
4032 g1_policy()->phase_times()->note_gc_end();
4033 g1_policy()->phase_times()->print(pause_time_sec);
4034 g1_policy()->print_detailed_heap_transition();
4035 } else {
4036 if (evacuation_failed()) {
4037 gc_cause_str.append("--");
4038 }
4039 gclog_or_tty->print("[%s", (const char*)gc_cause_str);
4040 g1_policy()->print_heap_transition();
4041 gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec);
4042 }
4043 }
4044 } 4049 }
4045 4050
4046 // It is not yet to safe to tell the concurrent mark to 4051 // It is not yet to safe to tell the concurrent mark to
4047 // start as we have some optional output below. We don't want the 4052 // start as we have some optional output below. We don't want the
4048 // output from the concurrent mark thread interfering with this 4053 // output from the concurrent mark thread interfering with this