7198130: G1: PrintReferenceGC output comes out of order

Mon, 17 Sep 2012 10:33:13 +0200

author
brutisso
date
Mon, 17 Sep 2012 10:33:13 +0200
changeset 4063
9646b7ff4d14
parent 4062
2a48c84f1d04
child 4064
8da5e203b993

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

src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp file | annotate | diff | comparison | revisions
src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp file | annotate | diff | comparison | revisions
src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp file | annotate | diff | comparison | revisions
src/share/vm/runtime/timer.cpp file | annotate | diff | comparison | revisions
     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      }

mercurial