提交 dd643c7f 编写于 作者: B brutisso

7160728: Introduce an extra logging level for G1 logging

Summary: Added log levels "fine", "finer" and "finest". Let PrintGC map to "fine" and PrintGCDetails map to "finer". Separated out the per worker information in the G1 logging to the "finest" level.
Reviewed-by: stefank, jwilhelm, tonyp, johnc
上级 078dc371
......@@ -29,6 +29,7 @@
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/g1OopClosures.inline.hpp"
#include "gc_implementation/g1/g1RemSet.hpp"
#include "gc_implementation/g1/heapRegion.inline.hpp"
......@@ -846,7 +847,7 @@ void ConcurrentMark::enter_first_sync_barrier(int task_num) {
clear_marking_state(concurrent() /* clear_overflow */);
force_overflow()->update();
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-mark-reset-for-overflow]");
......@@ -2105,7 +2106,7 @@ void ConcurrentMark::cleanup() {
double end = os::elapsedTime();
_cleanup_times.add((end - start) * 1000.0);
if (PrintGC || PrintGCDetails) {
if (G1Log::fine()) {
g1h->print_size_transition(gclog_or_tty,
start_used_bytes,
g1h->used(),
......@@ -2446,11 +2447,10 @@ void ConcurrentMark::weakRefsWork(bool clear_all_soft_refs) {
// Inner scope to exclude the cleaning of the string and symbol
// tables from the displayed time.
{
bool verbose = PrintGC && PrintGCDetails;
if (verbose) {
if (G1Log::finer()) {
gclog_or_tty->put(' ');
}
TraceTime t("GC ref-proc", verbose, false, gclog_or_tty);
TraceTime t("GC ref-proc", G1Log::finer(), false, gclog_or_tty);
ReferenceProcessor* rp = g1h->ref_processor_cm();
......
......@@ -26,6 +26,7 @@
#include "gc_implementation/g1/concurrentMarkThread.inline.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/g1MMUTracker.hpp"
#include "gc_implementation/g1/vm_operations_g1.hpp"
#include "memory/resourceArea.hpp"
......@@ -104,7 +105,7 @@ void ConcurrentMarkThread::run() {
double scan_start = os::elapsedTime();
if (!cm()->has_aborted()) {
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]");
......@@ -113,7 +114,7 @@ void ConcurrentMarkThread::run() {
_cm->scanRootRegions();
double scan_end = os::elapsedTime();
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf]",
......@@ -122,7 +123,7 @@ void ConcurrentMarkThread::run() {
}
double mark_start_sec = os::elapsedTime();
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-mark-start]");
......@@ -146,7 +147,7 @@ void ConcurrentMarkThread::run() {
os::sleep(current_thread, sleep_time_ms, false);
}
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-mark-end, %1.7lf sec]",
......@@ -165,7 +166,7 @@ void ConcurrentMarkThread::run() {
}
if (cm()->restart_for_overflow()) {
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-mark-restart-for-overflow]");
......@@ -211,7 +212,7 @@ void ConcurrentMarkThread::run() {
// reclaimed by cleanup.
double cleanup_start_sec = os::elapsedTime();
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-cleanup-start]");
......@@ -232,7 +233,7 @@ void ConcurrentMarkThread::run() {
g1h->reset_free_regions_coming();
double cleanup_end_sec = os::elapsedTime();
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-cleanup-end, %1.7lf]",
......@@ -273,7 +274,7 @@ void ConcurrentMarkThread::run() {
_sts.leave();
if (cm()->has_aborted()) {
if (PrintGC) {
if (G1Log::fine()) {
gclog_or_tty->date_stamp(PrintGCDateStamps);
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print_cr("[GC concurrent-mark-abort]");
......
......@@ -33,6 +33,7 @@
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp"
#include "gc_implementation/g1/g1EvacFailure.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/g1MarkSweep.hpp"
#include "gc_implementation/g1/g1OopClosures.inline.hpp"
#include "gc_implementation/g1/g1RemSet.inline.hpp"
......@@ -1255,10 +1256,10 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
// Timing
bool system_gc = (gc_cause() == GCCause::_java_lang_system_gc);
assert(!system_gc || explicit_gc, "invariant");
gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
TraceTime t(system_gc ? "Full GC (System.gc())" : "Full GC",
PrintGC, true, gclog_or_tty);
G1Log::fine(), true, gclog_or_tty);
TraceCollectorStats tcs(g1mm()->full_collection_counters());
TraceMemoryManagerStats tms(true /* fullGC */, gc_cause());
......@@ -1444,7 +1445,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
heap_region_iterate(&rebuild_rs);
}
if (PrintGC) {
if (G1Log::fine()) {
print_size_transition(gclog_or_tty, g1h_prev_used, used(), capacity());
}
......@@ -1917,6 +1918,8 @@ jint G1CollectedHeap::initialize() {
CollectedHeap::pre_initialize();
os::enable_vtime();
G1Log::init();
// Necessary to satisfy locking discipline assertions.
MutexLocker x(Heap_lock);
......@@ -3609,12 +3612,12 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
increment_total_full_collections();
}
// if PrintGCDetails is on, we'll print long statistics information
// 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(PrintGC && PrintGCDateStamps);
TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
TraceTime t(verbose_str, PrintGC && !PrintGCDetails, true, gclog_or_tty);
gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
TraceTime t(verbose_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty);
TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
......@@ -3931,8 +3934,8 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
}
// The closing of the inner scope, immediately above, will complete
// the PrintGC logging output. The record_collection_pause_end() call
// above will complete the logging output of PrintGCDetails.
// logging at the "fine" level. The record_collection_pause_end() call
// above will complete logging at the "finer" level.
//
// It is not yet to safe, however, to tell the concurrent mark to
// start as we have some optional output below. We don't want the
......@@ -5514,9 +5517,9 @@ void G1CollectedHeap::evacuate_collection_set() {
if (evacuation_failed()) {
remove_self_forwarding_pointers();
if (PrintGCDetails) {
if (G1Log::finer()) {
gclog_or_tty->print(" (to-space overflow)");
} else if (PrintGC) {
} else if (G1Log::fine()) {
gclog_or_tty->print("--");
}
}
......
......@@ -29,6 +29,7 @@
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/heapRegionRemSet.hpp"
#include "gc_implementation/shared/gcPolicyCounters.hpp"
#include "runtime/arguments.hpp"
......@@ -885,7 +886,7 @@ void G1CollectorPolicy::record_stop_world_start() {
void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
size_t start_used) {
if (PrintGCDetails) {
if (G1Log::finer()) {
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print("[GC pause");
gclog_or_tty->print(" (%s)", gcs_are_young() ? "young" : "mixed");
......@@ -1022,11 +1023,16 @@ void G1CollectorPolicy::print_par_stats(int level,
if (val > max)
max = val;
total += val;
buf.append(" %3.1lf", val);
if (G1Log::finest()) {
buf.append(" %.1lf", val);
}
}
if (G1Log::finest()) {
buf.append_and_print_cr("");
}
buf.append_and_print_cr("");
double avg = total / (double) no_of_gc_threads();
buf.append_and_print_cr(" Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf, Diff: %5.1lf]",
buf.append_and_print_cr(" Avg: %.1lf Min: %.1lf Max: %.1lf Diff: %.1lf]",
avg, min, max, max - min);
}
......@@ -1223,7 +1229,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
// These values are used to update the summary information that is
// displayed when TraceGen0Time is enabled, and are output as part
// of the PrintGCDetails output, in the non-parallel case.
// of the "finer" output, in the non-parallel case.
double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
......@@ -1356,8 +1362,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
}
}
// PrintGCDetails output
if (PrintGCDetails) {
if (G1Log::finer()) {
bool print_marking_info =
_g1->mark_in_progress() && !last_pause_included_initial_mark;
......@@ -1376,11 +1381,15 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
}
print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers);
if (G1Log::finest()) {
print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers);
}
print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
print_par_stats(2, "Termination", _par_last_termination_times_ms);
print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts);
if (G1Log::finest()) {
print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts);
}
for (int i = 0; i < _parallel_gc_threads; i++) {
_par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
......@@ -1406,7 +1415,9 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
print_stats(1, "SATB Filtering", satb_filtering_time);
}
print_stats(1, "Update RS", update_rs_time);
print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers);
if (G1Log::finest()) {
print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers);
}
print_stats(1, "Scan RS", scan_rs_time);
print_stats(1, "Object Copying", obj_copy_time);
}
......@@ -1610,7 +1621,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
proper_unit_for_byte_size((bytes))
void G1CollectorPolicy::print_heap_transition() {
if (PrintGCDetails) {
if (G1Log::finer()) {
YoungList* young_list = _g1->young_list();
size_t eden_bytes = young_list->eden_used_bytes();
size_t survivor_bytes = young_list->survivor_used_bytes();
......@@ -1637,7 +1648,7 @@ void G1CollectorPolicy::print_heap_transition() {
EXT_SIZE_PARAMS(capacity));
_prev_eden_capacity = eden_capacity;
} else if (PrintGC) {
} else if (G1Log::fine()) {
_g1->print_size_transition(gclog_or_tty,
_cur_collection_pause_used_at_start_bytes,
_g1->used(), _g1->capacity());
......
/*
* Copyright (c) 2012, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*
*/
#include "precompiled.hpp"
#include "gc_implementation/g1/g1_globals.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "runtime/globals.hpp"
G1Log::LogLevel G1Log::_level = G1Log::LevelNone;
// If G1LogLevel has not been set up we will use the values of PrintGC
// and PrintGCDetails for the logging level.
// - PrintGC maps to "fine".
// - PrintGCDetails maps to "finer".
void G1Log::init() {
if (G1LogLevel != NULL && G1LogLevel[0] != '\0') {
if (strncmp("none", G1LogLevel, 4) == 0 && G1LogLevel[4] == '\0') {
_level = LevelNone;
} else if (strncmp("fine", G1LogLevel, 4) == 0 && G1LogLevel[4] == '\0') {
_level = LevelFine;
} else if (strncmp("finer", G1LogLevel, 5) == 0 && G1LogLevel[5] == '\0') {
_level = LevelFiner;
} else if (strncmp("finest", G1LogLevel, 6) == 0 && G1LogLevel[6] == '\0') {
_level = LevelFinest;
} else {
warning("Unknown logging level '%s', should be one of 'fine', 'finer' or 'finest'.", G1LogLevel);
}
} else {
if (PrintGCDetails) {
_level = LevelFiner;
} else if (PrintGC) {
_level = LevelFine;
}
}
}
/*
* Copyright (c) 2012, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*
*/
#ifndef SHARE_VM_GC_IMPLEMENTATION_G1_G1LOG_HPP
#define SHARE_VM_GC_IMPLEMENTATION_G1_G1LOG_HPP
#include "memory/allocation.hpp"
class G1Log : public AllStatic {
typedef enum {
LevelNone,
LevelFine,
LevelFiner,
LevelFinest
} LogLevel;
static LogLevel _level;
public:
inline static bool fine() {
return _level >= LevelFine;
}
inline static bool finer() {
return _level >= LevelFiner;
}
inline static bool finest() {
return _level == LevelFinest;
}
static void init();
};
#endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1LOG_HPP
......@@ -29,6 +29,7 @@
#include "classfile/vmSymbols.hpp"
#include "code/codeCache.hpp"
#include "code/icBuffer.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/g1MarkSweep.hpp"
#include "memory/gcLocker.hpp"
#include "memory/genCollectedHeap.hpp"
......@@ -126,7 +127,7 @@ void G1MarkSweep::allocate_stacks() {
void G1MarkSweep::mark_sweep_phase1(bool& marked_for_unloading,
bool clear_all_softrefs) {
// Recursively traverse all live objects and mark them
TraceTime tm("phase 1", PrintGC && Verbose, true, gclog_or_tty);
TraceTime tm("phase 1", G1Log::fine() && Verbose, true, gclog_or_tty);
GenMarkSweep::trace(" 1");
SharedHeap* sh = SharedHeap::heap();
......@@ -291,7 +292,7 @@ void G1MarkSweep::mark_sweep_phase2() {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
Generation* pg = g1h->perm_gen();
TraceTime tm("phase 2", PrintGC && Verbose, true, gclog_or_tty);
TraceTime tm("phase 2", G1Log::fine() && Verbose, true, gclog_or_tty);
GenMarkSweep::trace("2");
FindFirstRegionClosure cl;
......@@ -335,7 +336,7 @@ void G1MarkSweep::mark_sweep_phase3() {
Generation* pg = g1h->perm_gen();
// Adjust the pointers to reflect the new locations
TraceTime tm("phase 3", PrintGC && Verbose, true, gclog_or_tty);
TraceTime tm("phase 3", G1Log::fine() && Verbose, true, gclog_or_tty);
GenMarkSweep::trace("3");
SharedHeap* sh = SharedHeap::heap();
......@@ -399,7 +400,7 @@ void G1MarkSweep::mark_sweep_phase4() {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
Generation* pg = g1h->perm_gen();
TraceTime tm("phase 4", PrintGC && Verbose, true, gclog_or_tty);
TraceTime tm("phase 4", G1Log::fine() && Verbose, true, gclog_or_tty);
GenMarkSweep::trace("4");
pg->compact();
......
......@@ -26,7 +26,6 @@
#define SHARE_VM_GC_IMPLEMENTATION_G1_G1_GLOBALS_HPP
#include "runtime/globals.hpp"
//
// Defines all globals flags used by the garbage-first compiler.
//
......@@ -309,7 +308,10 @@
\
develop(uintx, G1OldCSetRegionThresholdPercent, 10, \
"An upper bound for the number of old CSet regions expressed " \
"as a percentage of the heap size.")
"as a percentage of the heap size.") \
\
experimental(ccstr, G1LogLevel, NULL, \
"Log level for G1 logging: fine, finer, finest")
G1_FLAGS(DECLARE_DEVELOPER_FLAG, DECLARE_PD_DEVELOPER_FLAG, DECLARE_PRODUCT_FLAG, DECLARE_PD_PRODUCT_FLAG, DECLARE_DIAGNOSTIC_FLAG, DECLARE_EXPERIMENTAL_FLAG, DECLARE_NOTPRODUCT_FLAG, DECLARE_MANAGEABLE_FLAG, DECLARE_PRODUCT_RW_FLAG)
......
......@@ -26,6 +26,7 @@
#include "gc_implementation/g1/concurrentMarkThread.inline.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/vm_operations_g1.hpp"
#include "gc_implementation/shared/isGCActiveMark.hpp"
#include "gc_implementation/g1/vm_operations_g1.hpp"
......@@ -223,9 +224,9 @@ void VM_CGC_Operation::release_and_notify_pending_list_lock() {
}
void VM_CGC_Operation::doit() {
gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
TraceTime t(_printGCMessage, PrintGC, true, gclog_or_tty);
gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
TraceTime t(_printGCMessage, G1Log::fine(), true, gclog_or_tty);
SharedHeap* sh = SharedHeap::heap();
// This could go away if CollectedHeap gave access to _gc_is_active...
if (sh != NULL) {
......
Markdown is supported
0% .
You are about to add 0 people to the discussion. Proceed with caution.
先完成此消息的编辑!
想要评论请 注册