Mon, 17 Sep 2012 10:33:13 +0200
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
1.1 --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Mon Sep 17 10:46:59 2012 -0400 1.2 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Mon Sep 17 10:33:13 2012 +0200 1.3 @@ -3425,10 +3425,7 @@ 1.4 _wallclock.stop(); 1.5 if (PrintGCDetails) { 1.6 gclog_or_tty->date_stamp(PrintGCDateStamps); 1.7 - if (PrintGCTimeStamps) { 1.8 - gclog_or_tty->stamp(); 1.9 - gclog_or_tty->print(": "); 1.10 - } 1.11 + gclog_or_tty->stamp(PrintGCTimeStamps); 1.12 gclog_or_tty->print("[%s-concurrent-%s: %3.3f/%3.3f secs]", 1.13 _collector->cmsGen()->short_name(), 1.14 _phase, _collector->timerValue(), _wallclock.seconds());
2.1 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Sep 17 10:46:59 2012 -0400 2.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Sep 17 10:33:13 2012 +0200 2.3 @@ -3663,6 +3663,43 @@ 2.4 } 2.5 #endif // TASKQUEUE_STATS 2.6 2.7 +void G1CollectedHeap::log_gc_header() { 2.8 + if (!G1Log::fine()) { 2.9 + return; 2.10 + } 2.11 + 2.12 + gclog_or_tty->date_stamp(PrintGCDateStamps); 2.13 + gclog_or_tty->stamp(PrintGCTimeStamps); 2.14 + 2.15 + GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) 2.16 + .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") 2.17 + .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); 2.18 + 2.19 + gclog_or_tty->print("[%s", (const char*)gc_cause_str); 2.20 +} 2.21 + 2.22 +void G1CollectedHeap::log_gc_footer(double pause_time_sec) { 2.23 + if (!G1Log::fine()) { 2.24 + return; 2.25 + } 2.26 + 2.27 + if (G1Log::finer()) { 2.28 + if (evacuation_failed()) { 2.29 + gclog_or_tty->print(" (to-space exhausted)"); 2.30 + } 2.31 + gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec); 2.32 + g1_policy()->phase_times()->note_gc_end(); 2.33 + g1_policy()->phase_times()->print(pause_time_sec); 2.34 + g1_policy()->print_detailed_heap_transition(); 2.35 + } else { 2.36 + if (evacuation_failed()) { 2.37 + gclog_or_tty->print("--"); 2.38 + } 2.39 + g1_policy()->print_heap_transition(); 2.40 + gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec); 2.41 + } 2.42 +} 2.43 + 2.44 bool 2.45 G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { 2.46 assert_at_safepoint(true /* should_be_vm_thread */); 2.47 @@ -3705,17 +3742,13 @@ 2.48 // full collection counter. 2.49 increment_old_marking_cycles_started(); 2.50 } 2.51 - // if the log level is "finer" is on, we'll print long statistics information 2.52 - // in the collector policy code, so let's not print this as the output 2.53 - // is messy if we do. 2.54 - gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); 2.55 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); 2.56 2.57 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? 2.58 workers()->active_workers() : 1); 2.59 double pause_start_sec = os::elapsedTime(); 2.60 g1_policy()->phase_times()->note_gc_start(active_workers); 2.61 - bool initial_mark_gc = g1_policy()->during_initial_mark_pause(); 2.62 + log_gc_header(); 2.63 2.64 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); 2.65 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); 2.66 @@ -4012,35 +4045,7 @@ 2.67 2.68 gc_epilogue(false); 2.69 2.70 - if (G1Log::fine()) { 2.71 - if (PrintGCTimeStamps) { 2.72 - gclog_or_tty->stamp(); 2.73 - gclog_or_tty->print(": "); 2.74 - } 2.75 - 2.76 - GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) 2.77 - .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") 2.78 - .append(initial_mark_gc ? " (initial-mark)" : ""); 2.79 - 2.80 - double pause_time_sec = os::elapsedTime() - pause_start_sec; 2.81 - 2.82 - if (G1Log::finer()) { 2.83 - if (evacuation_failed()) { 2.84 - gc_cause_str.append(" (to-space exhausted)"); 2.85 - } 2.86 - gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_sec); 2.87 - g1_policy()->phase_times()->note_gc_end(); 2.88 - g1_policy()->phase_times()->print(pause_time_sec); 2.89 - g1_policy()->print_detailed_heap_transition(); 2.90 - } else { 2.91 - if (evacuation_failed()) { 2.92 - gc_cause_str.append("--"); 2.93 - } 2.94 - gclog_or_tty->print("[%s", (const char*)gc_cause_str); 2.95 - g1_policy()->print_heap_transition(); 2.96 - gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec); 2.97 - } 2.98 - } 2.99 + log_gc_footer(os::elapsedTime() - pause_start_sec); 2.100 } 2.101 2.102 // It is not yet to safe to tell the concurrent mark to
3.1 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Mon Sep 17 10:46:59 2012 -0400 3.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp Mon Sep 17 10:33:13 2012 +0200 3.3 @@ -408,6 +408,9 @@ 3.4 void verify_before_gc(); 3.5 void verify_after_gc(); 3.6 3.7 + void log_gc_header(); 3.8 + void log_gc_footer(double pause_time_sec); 3.9 + 3.10 // These are macros so that, if the assert fires, we get the correct 3.11 // line number, file, etc. 3.12
4.1 --- a/src/share/vm/runtime/timer.cpp Mon Sep 17 10:46:59 2012 -0400 4.2 +++ b/src/share/vm/runtime/timer.cpp Mon Sep 17 10:33:13 2012 +0200 4.3 @@ -120,10 +120,7 @@ 4.4 4.5 if (_active) { 4.6 _accum = NULL; 4.7 - if (PrintGCTimeStamps) { 4.8 - _logfile->stamp(); 4.9 - _logfile->print(": "); 4.10 - } 4.11 + _logfile->stamp(PrintGCTimeStamps); 4.12 _logfile->print("[%s", title); 4.13 _logfile->flush(); 4.14 _t.start(); 4.15 @@ -141,10 +138,7 @@ 4.16 _logfile = (logfile != NULL) ? logfile : tty; 4.17 if (_active) { 4.18 if (_verbose) { 4.19 - if (PrintGCTimeStamps) { 4.20 - _logfile->stamp(); 4.21 - _logfile->print(": "); 4.22 - } 4.23 + _logfile->stamp(PrintGCTimeStamps); 4.24 _logfile->print("[%s", title); 4.25 _logfile->flush(); 4.26 }