From 44d9264c04de5c4b762fde21f6b36a9b9c71479e Mon Sep 17 00:00:00 2001 From: brutisso Date: Tue, 15 May 2012 10:25:06 +0200 Subject: [PATCH] 7166894: Add gc cause to GC logging for all collectors Reviewed-by: mgerdin, johnc --- .../concurrentMarkSweepGeneration.cpp | 4 +-- .../concurrentMarkSweepGeneration.hpp | 2 +- .../concurrentMarkSweep/vmCMSOperations.cpp | 4 +-- .../gc_implementation/g1/g1CollectedHeap.cpp | 15 +++------ .../g1/g1CollectorPolicy.cpp | 5 ++- .../parNew/parNewGeneration.cpp | 2 +- .../parallelScavenge/psMarkSweep.cpp | 10 ++---- .../parallelScavenge/psParallelCompact.cpp | 13 ++------ .../parallelScavenge/psScavenge.cpp | 2 +- src/share/vm/gc_interface/gcCause.hpp | 32 +++++++++++++++++++ src/share/vm/memory/defNewGeneration.cpp | 2 +- src/share/vm/memory/genCollectedHeap.cpp | 15 ++------- src/share/vm/memory/genMarkSweep.cpp | 2 +- src/share/vm/runtime/arguments.cpp | 8 +++++ src/share/vm/runtime/globals.hpp | 5 ++- src/share/vm/runtime/java.hpp | 8 +++++ 16 files changed, 75 insertions(+), 54 deletions(-) diff --git a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp index 5825a5772..938e94efc 100644 --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp @@ -6332,10 +6332,10 @@ void CMSCollector::reset(bool asynch) { ) } -void CMSCollector::do_CMS_operation(CMS_op_type op) { +void CMSCollector::do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause) { gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - TraceTime t("GC", PrintGC, !PrintGCDetails, gclog_or_tty); + TraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty); TraceCollectorStats tcs(counters()); switch (op) { diff --git a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp index a84253888..ecc60cc3e 100644 --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp @@ -717,7 +717,7 @@ class CMSCollector: public CHeapObj { CMS_op_checkpointRootsFinal }; - void do_CMS_operation(CMS_op_type op); + void do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause); bool stop_world_and_do(CMS_op_type op); OopTaskQueueSet* task_queues() { return _task_queues; } diff --git a/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp b/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp index c3b9d54be..3b8d5aa08 100644 --- a/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp @@ -146,7 +146,7 @@ void VM_CMS_Initial_Mark::doit() { VM_CMS_Operation::verify_before_gc(); IsGCActiveMark x; // stop-world GC active - _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsInitial); + _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsInitial, gch->gc_cause()); VM_CMS_Operation::verify_after_gc(); #ifndef USDT2 @@ -178,7 +178,7 @@ void VM_CMS_Final_Remark::doit() { VM_CMS_Operation::verify_before_gc(); IsGCActiveMark x; // stop-world GC active - _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsFinal); + _collector->do_CMS_operation(CMSCollector::CMS_op_checkpointRootsFinal, gch->gc_cause()); VM_CMS_Operation::verify_after_gc(); #ifndef USDT2 diff --git a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp index fa71befcf..9d1f9d92d 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @@ -1252,10 +1252,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc, gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); - char verbose_str[128]; - sprintf(verbose_str, "Full GC (%s)", GCCause::to_string(gc_cause())); - TraceTime t(verbose_str, G1Log::fine(), true, gclog_or_tty); - + TraceTime t(GCCauseString("Full GC", gc_cause()), G1Log::fine(), true, gclog_or_tty); TraceCollectorStats tcs(g1mm()->full_collection_counters()); TraceMemoryManagerStats tms(true /* fullGC */, gc_cause()); @@ -3600,12 +3597,10 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); - char verbose_str[128]; - sprintf(verbose_str, "GC pause (%s) (%s)%s", - GCCause::to_string(gc_cause()), - g1_policy()->gcs_are_young() ? "young" : "mixed", - g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); - TraceTime t(verbose_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty); + 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)" : ""); + TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty); TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); diff --git a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp index 05dea1c48..2050f6f5b 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @@ -886,9 +886,8 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, size_t start_used) { if (G1Log::finer()) { gclog_or_tty->stamp(PrintGCTimeStamps); - gclog_or_tty->print("[GC pause (%s) (%s)", - GCCause::to_string(_g1->gc_cause()), - gcs_are_young() ? "young" : "mixed"); + gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause()) + .append(gcs_are_young() ? " (young)" : " (mixed)")); } // We only need to do this here as the policy will only be applied diff --git a/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp b/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp index 4f64dff08..96ae468f0 100644 --- a/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp +++ b/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp @@ -916,7 +916,7 @@ void ParNewGeneration::collect(bool full, size_policy->minor_collection_begin(); } - TraceTime t1("GC", PrintGC && !PrintGCDetails, true, gclog_or_tty); + TraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, gclog_or_tty); // Capture heap used before collection (for printing). size_t gch_prev_used = gch->used(); diff --git a/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp b/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp index ad599ae32..0ef975236 100644 --- a/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp +++ b/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp @@ -160,16 +160,10 @@ bool PSMarkSweep::invoke_no_policy(bool clear_all_softrefs) { { HandleMark hm; - const bool is_system_gc = gc_cause == GCCause::_java_lang_system_gc; - // This is useful for debugging but don't change the output the - // the customer sees. - const char* gc_cause_str = "Full GC"; - if (is_system_gc && PrintGCDetails) { - gc_cause_str = "Full GC (System)"; - } + gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - TraceTime t1(gc_cause_str, PrintGC, !PrintGCDetails, gclog_or_tty); + TraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(true /* Full GC */,gc_cause); diff --git a/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp b/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp index 354b3d043..8e7c74e44 100644 --- a/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp +++ b/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp @@ -2047,17 +2047,9 @@ bool PSParallelCompact::invoke_no_policy(bool maximum_heap_compaction) { gc_task_manager()->task_idle_workers(); heap->set_par_threads(gc_task_manager()->active_workers()); - const bool is_system_gc = gc_cause == GCCause::_java_lang_system_gc; - - // This is useful for debugging but don't change the output the - // the customer sees. - const char* gc_cause_str = "Full GC"; - if (is_system_gc && PrintGCDetails) { - gc_cause_str = "Full GC (System)"; - } gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - TraceTime t1(gc_cause_str, PrintGC, !PrintGCDetails, gclog_or_tty); + TraceTime t1(GCCauseString("Full GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(true /* Full GC */,gc_cause); @@ -2090,7 +2082,8 @@ bool PSParallelCompact::invoke_no_policy(bool maximum_heap_compaction) { } #endif // #ifndef PRODUCT - bool max_on_system_gc = UseMaximumCompactionOnSystemGC && is_system_gc; + bool max_on_system_gc = UseMaximumCompactionOnSystemGC + && gc_cause == GCCause::_java_lang_system_gc; summary_phase(vmthread_cm, maximum_heap_compaction || max_on_system_gc); COMPILER2_PRESENT(assert(DerivedPointerTable::is_active(), "Sanity")); diff --git a/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp b/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp index 984b1a452..65ece052d 100644 --- a/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp +++ b/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp @@ -325,7 +325,7 @@ bool PSScavenge::invoke_no_policy() { gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - TraceTime t1("GC", PrintGC, !PrintGCDetails, gclog_or_tty); + TraceTime t1(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(false /* not full GC */,gc_cause); diff --git a/src/share/vm/gc_interface/gcCause.hpp b/src/share/vm/gc_interface/gcCause.hpp index ae14115d7..8866d7675 100644 --- a/src/share/vm/gc_interface/gcCause.hpp +++ b/src/share/vm/gc_interface/gcCause.hpp @@ -88,4 +88,36 @@ class GCCause : public AllStatic { static const char* to_string(GCCause::Cause cause); }; +// Helper class for doing logging that includes the GC Cause +// as a string. +class GCCauseString : StackObj { + private: + static const int _length = 128; + char _buffer[_length]; + int _position; + + public: + GCCauseString(const char* prefix, GCCause::Cause cause) { + if (PrintGCCause) { + _position = jio_snprintf(_buffer, _length, "%s (%s)", prefix, GCCause::to_string(cause)); + } else { + _position = jio_snprintf(_buffer, _length, "%s", prefix); + } + assert(_position >= 0 && _position <= _length, + err_msg("Need to increase the buffer size in GCCauseString? %d", _position)); + } + + GCCauseString& append(const char* str) { + int res = jio_snprintf(_buffer + _position, _length - _position, "%s", str); + _position += res; + assert(res >= 0 && _position <= _length, + err_msg("Need to increase the buffer size in GCCauseString? %d", res)); + return *this; + } + + operator const char*() { + return _buffer; + } +}; + #endif // SHARE_VM_GC_INTERFACE_GCCAUSE_HPP diff --git a/src/share/vm/memory/defNewGeneration.cpp b/src/share/vm/memory/defNewGeneration.cpp index 315a38248..452f63073 100644 --- a/src/share/vm/memory/defNewGeneration.cpp +++ b/src/share/vm/memory/defNewGeneration.cpp @@ -548,7 +548,7 @@ void DefNewGeneration::collect(bool full, init_assuming_no_promotion_failure(); - TraceTime t1("GC", PrintGC && !PrintGCDetails, true, gclog_or_tty); + TraceTime t1(GCCauseString("GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, gclog_or_tty); // Capture heap used before collection (for printing). size_t gch_prev_used = gch->used(); diff --git a/src/share/vm/memory/genCollectedHeap.cpp b/src/share/vm/memory/genCollectedHeap.cpp index 10c327454..40f5afda4 100644 --- a/src/share/vm/memory/genCollectedHeap.cpp +++ b/src/share/vm/memory/genCollectedHeap.cpp @@ -480,26 +480,15 @@ void GenCollectedHeap::do_collection(bool full, const size_t perm_prev_used = perm_gen()->used(); print_heap_before_gc(); - if (Verbose) { - gclog_or_tty->print_cr("GC Cause: %s", GCCause::to_string(gc_cause())); - } { FlagSetting fl(_is_gc_active, true); bool complete = full && (max_level == (n_gens()-1)); - const char* gc_cause_str = "GC "; - if (complete) { - GCCause::Cause cause = gc_cause(); - if (cause == GCCause::_java_lang_system_gc) { - gc_cause_str = "Full GC (System) "; - } else { - gc_cause_str = "Full GC "; - } - } + const char* gc_cause_prefix = complete ? "Full GC" : "GC"; gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps); TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty); - TraceTime t(gc_cause_str, PrintGCDetails, false, gclog_or_tty); + TraceTime t(GCCauseString(gc_cause_prefix, gc_cause()), PrintGCDetails, false, gclog_or_tty); gc_prologue(complete); increment_total_collections(complete); diff --git a/src/share/vm/memory/genMarkSweep.cpp b/src/share/vm/memory/genMarkSweep.cpp index d5cf4dc75..4d13fbb22 100644 --- a/src/share/vm/memory/genMarkSweep.cpp +++ b/src/share/vm/memory/genMarkSweep.cpp @@ -76,7 +76,7 @@ void GenMarkSweep::invoke_at_safepoint(int level, ReferenceProcessor* rp, _ref_processor = rp; rp->setup_policy(clear_all_softrefs); - TraceTime t1("Full GC", PrintGC && !PrintGCDetails, true, gclog_or_tty); + TraceTime t1(GCCauseString("Full GC", gch->gc_cause()), PrintGC && !PrintGCDetails, true, gclog_or_tty); // When collecting the permanent generation methodOops may be moving, // so we either have to flush all bcp data or convert it into bci. diff --git a/src/share/vm/runtime/arguments.cpp b/src/share/vm/runtime/arguments.cpp index 8deacc6f5..7f3ea3ecf 100644 --- a/src/share/vm/runtime/arguments.cpp +++ b/src/share/vm/runtime/arguments.cpp @@ -3092,6 +3092,14 @@ jint Arguments::parse(const JavaVMInitArgs* args) { PrintGC = true; } + if (!JDK_Version::is_gte_jdk18x_version()) { + // To avoid changing the log format for 7 updates this flag is only + // true by default in JDK8 and above. + if (FLAG_IS_DEFAULT(PrintGCCause)) { + FLAG_SET_DEFAULT(PrintGCCause, false); + } + } + // Set object alignment values. set_object_alignment(); diff --git a/src/share/vm/runtime/globals.hpp b/src/share/vm/runtime/globals.hpp index 7ad4f9a04..d030b4f17 100644 --- a/src/share/vm/runtime/globals.hpp +++ b/src/share/vm/runtime/globals.hpp @@ -3902,7 +3902,10 @@ class CommandLineFlags { " of this flag is true for JDK 6 and earlier") \ \ diagnostic(bool, WhiteBoxAPI, false, \ - "Enable internal testing APIs") + "Enable internal testing APIs") \ + \ + product(bool, PrintGCCause, true, \ + "Include GC cause in GC logging") /* * Macros for factoring of globals diff --git a/src/share/vm/runtime/java.hpp b/src/share/vm/runtime/java.hpp index 307fcc2fb..102fd6b7a 100644 --- a/src/share/vm/runtime/java.hpp +++ b/src/share/vm/runtime/java.hpp @@ -206,6 +206,10 @@ class JDK_Version VALUE_OBJ_CLASS_SPEC { return current().compare_major(7) == 0; } + static bool is_jdk18x_version() { + return current().compare_major(8) == 0; + } + static bool is_gte_jdk13x_version() { return current().compare_major(3) >= 0; } @@ -225,6 +229,10 @@ class JDK_Version VALUE_OBJ_CLASS_SPEC { static bool is_gte_jdk17x_version() { return current().compare_major(7) >= 0; } + + static bool is_gte_jdk18x_version() { + return current().compare_major(8) >= 0; + } }; #endif // SHARE_VM_RUNTIME_JAVA_HPP -- GitLab