src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp
Index Unified diffs Context diffs Sdiffs Patch New Old Previous File Next File hs-gc-g1-gc-timestamp Cdiff src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

Print this page
rev 3618 : 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

*** 3661,3670 **** --- 3661,3709 ---- task_queue(i)->stats.reset(); } } #endif // TASKQUEUE_STATS + void G1CollectedHeap::log_gc_header() { + if (!G1Log::fine()) { + return; + } + gclog_or_tty->date_stamp(PrintGCDateStamps); + if (PrintGCTimeStamps) { + gclog_or_tty->stamp(); + gclog_or_tty->print(": "); + } + + GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) + .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") + .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); + + gclog_or_tty->print("[%s", (const char*)gc_cause_str); + } + + void G1CollectedHeap::log_gc_footer(double pause_time_sec) { + if (!G1Log::fine()) { + return; + } + + if (G1Log::finer()) { + if (evacuation_failed()) { + gclog_or_tty->print(" (to-space exhausted)"); + } + gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec); + g1_policy()->phase_times()->note_gc_end(); + g1_policy()->phase_times()->print(pause_time_sec); + g1_policy()->print_detailed_heap_transition(); + } else { + if (evacuation_failed()) { + gclog_or_tty->print("--"); + } + g1_policy()->print_heap_transition(); + gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec); + } + } + bool G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { assert_at_safepoint(true /* should_be_vm_thread */); guarantee(!is_gc_active(), "collection is not reentrant");
*** 3703,3723 **** if (g1_policy()->during_initial_mark_pause()) { // We are about to start a marking cycle, so we increment the // full collection counter. increment_old_marking_cycles_started(); } - // if the log level is "finer" is on, we'll print long statistics information - // in the collector policy code, so let's not print this as the output - // is messy if we do. - gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? workers()->active_workers() : 1); double pause_start_sec = os::elapsedTime(); g1_policy()->phase_times()->note_gc_start(active_workers); ! bool initial_mark_gc = g1_policy()->during_initial_mark_pause(); TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); // If the secondary_free_list is not empty, append it to the --- 3742,3758 ---- if (g1_policy()->during_initial_mark_pause()) { // We are about to start a marking cycle, so we increment the // full collection counter. increment_old_marking_cycles_started(); } TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? workers()->active_workers() : 1); double pause_start_sec = os::elapsedTime(); g1_policy()->phase_times()->note_gc_start(active_workers); ! log_gc_header(); TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); // If the secondary_free_list is not empty, append it to the
*** 4010,4048 **** ParallelTaskTerminator::print_termination_counts(); #endif gc_epilogue(false); ! if (G1Log::fine()) { ! if (PrintGCTimeStamps) { ! gclog_or_tty->stamp(); ! gclog_or_tty->print(": "); ! } ! ! GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) ! .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") ! .append(initial_mark_gc ? " (initial-mark)" : ""); ! ! double pause_time_sec = os::elapsedTime() - pause_start_sec; ! ! if (G1Log::finer()) { ! if (evacuation_failed()) { ! gc_cause_str.append(" (to-space exhausted)"); ! } ! gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_sec); ! g1_policy()->phase_times()->note_gc_end(); ! g1_policy()->phase_times()->print(pause_time_sec); ! g1_policy()->print_detailed_heap_transition(); ! } else { ! if (evacuation_failed()) { ! gc_cause_str.append("--"); ! } ! gclog_or_tty->print("[%s", (const char*)gc_cause_str); ! g1_policy()->print_heap_transition(); ! gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec); ! } ! } } // It is not yet to safe to tell the concurrent mark to // start as we have some optional output below. We don't want the // output from the concurrent mark thread interfering with this --- 4045,4055 ---- ParallelTaskTerminator::print_termination_counts(); #endif gc_epilogue(false); ! log_gc_footer(os::elapsedTime() - pause_start_sec); } // It is not yet to safe to tell the concurrent mark to // start as we have some optional output below. We don't want the // output from the concurrent mark thread interfering with this
src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp
Index Unified diffs Context diffs Sdiffs Patch New Old Previous File Next File