--- old/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp 2012-05-08 16:12:32.299252500 +0200 +++ new/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp 2012-05-08 16:12:31.257192900 +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) { --- old/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp 2012-05-08 16:12:32.220248000 +0200 +++ new/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp 2012-05-08 16:12:31.051181200 +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; } --- old/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp 2012-05-08 16:12:32.692275000 +0200 +++ new/src/share/vm/gc_implementation/concurrentMarkSweep/vmCMSOperations.cpp 2012-05-08 16:12:31.716219200 +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 --- old/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp 2012-05-08 16:12:33.587326200 +0200 +++ new/src/share/vm/gc_implementation/parNew/parNewGeneration.cpp 2012-05-08 16:12:32.626271200 +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(); --- old/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp 2012-05-08 16:12:33.594326600 +0200 +++ new/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp 2012-05-08 16:12:32.744278000 +0200 @@ -885,10 +885,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", 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 --- old/src/share/vm/memory/defNewGeneration.cpp 2012-05-08 16:12:34.283366000 +0200 +++ new/src/share/vm/memory/defNewGeneration.cpp 2012-05-08 16:12:33.341312100 +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(); --- old/src/share/vm/gc_interface/gcCause.hpp 2012-05-08 16:12:34.852398600 +0200 +++ new/src/share/vm/gc_interface/gcCause.hpp 2012-05-08 16:12:32.906287300 +0200 @@ -88,4 +88,35 @@ 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) { + position += jio_snprintf(buffer + position, length - position, "%", str); + assert(position > 0 && position <= length, + err_msg("Need to increase the buffer size in GCCauseString? %d", position)); + return *this; + } + + operator const char*() { + return buffer; + } +}; + #endif // SHARE_VM_GC_INTERFACE_GCCAUSE_HPP --- old/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp 2012-05-08 16:12:34.898401200 +0200 +++ new/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp 2012-05-08 16:12:33.345312400 +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); --- old/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp 2012-05-08 16:12:35.303424400 +0200 +++ new/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp 2012-05-08 16:12:33.751335600 +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); --- old/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp 2012-05-08 16:12:35.675445600 +0200 +++ new/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp 2012-05-08 16:12:33.182303000 +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,11 @@ 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); + TraceTime t(GCCauseString("GC pause", gc_cause()) + .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") + .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""), + G1Log::fine() && !G1Log::finer(), + true, gclog_or_tty); TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); --- old/src/share/vm/memory/genCollectedHeap.cpp 2012-05-08 16:12:35.816453700 +0200 +++ new/src/share/vm/memory/genCollectedHeap.cpp 2012-05-08 16:12:34.738392000 +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 "; - } - } + 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); --- old/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp 2012-05-08 16:12:35.754450200 +0200 +++ new/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp 2012-05-08 16:12:34.064353500 +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")); --- old/src/share/vm/memory/genMarkSweep.cpp 2012-05-08 16:12:41.643787000 +0200 +++ new/src/share/vm/memory/genMarkSweep.cpp 2012-05-08 16:12:41.178760400 +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. --- old/src/share/vm/runtime/globals.hpp 2012-05-08 16:12:41.737792400 +0200 +++ new/src/share/vm/runtime/globals.hpp 2012-05-08 16:12:41.300767400 +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