# HG changeset patch # User brutisso # Date 1337070306 -7200 # Node ID 9d679effd28cdfc473eaa9bfefd6f31638061140 # Parent cdfa5139bd5831149033a32edfcd35f713fa2a81 7166894: Add gc cause to GC logging for all collectors Reviewed-by: mgerdin, johnc diff -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Tue May 15 10:25:06 2012 +0200 @@ -6332,10 +6332,10 @@ ) } -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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp Tue May 15 10:25:06 2012 +0200 @@ -717,7 +717,7 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp --- a/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp Tue May 15 10:25:06 2012 +0200 @@ -146,7 +146,7 @@ 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 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Tue May 15 10:25:06 2012 +0200 @@ -1252,10 +1252,7 @@ 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 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Tue May 15 10:25:06 2012 +0200 @@ -886,9 +886,8 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/parNew/parNewGeneration.cpp --- a/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp Tue May 15 10:25:06 2012 +0200 @@ -916,7 +916,7 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp Tue May 15 10:25:06 2012 +0200 @@ -160,16 +160,10 @@ { 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp Tue May 15 10:25:06 2012 +0200 @@ -2047,17 +2047,9 @@ 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 @@ } #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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp --- a/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp Tue May 15 10:25:06 2012 +0200 @@ -325,7 +325,7 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/gc_interface/gcCause.hpp --- a/src/share/vm/gc_interface/gcCause.hpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/gc_interface/gcCause.hpp Tue May 15 10:25:06 2012 +0200 @@ -88,4 +88,36 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/memory/defNewGeneration.cpp --- a/src/share/vm/memory/defNewGeneration.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/memory/defNewGeneration.cpp Tue May 15 10:25:06 2012 +0200 @@ -548,7 +548,7 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/memory/genCollectedHeap.cpp --- a/src/share/vm/memory/genCollectedHeap.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/memory/genCollectedHeap.cpp Tue May 15 10:25:06 2012 +0200 @@ -480,26 +480,15 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/memory/genMarkSweep.cpp --- a/src/share/vm/memory/genMarkSweep.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/memory/genMarkSweep.cpp Tue May 15 10:25:06 2012 +0200 @@ -76,7 +76,7 @@ _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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/runtime/arguments.cpp --- a/src/share/vm/runtime/arguments.cpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/runtime/arguments.cpp Tue May 15 10:25:06 2012 +0200 @@ -3092,6 +3092,14 @@ 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/runtime/globals.hpp --- a/src/share/vm/runtime/globals.hpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/runtime/globals.hpp Tue May 15 10:25:06 2012 +0200 @@ -3902,7 +3902,10 @@ " 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 -r cdfa5139bd58 -r 9d679effd28c src/share/vm/runtime/java.hpp --- a/src/share/vm/runtime/java.hpp Tue May 15 22:26:37 2012 +0200 +++ b/src/share/vm/runtime/java.hpp Tue May 15 10:25:06 2012 +0200 @@ -206,6 +206,10 @@ 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 @@ 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