7145537: minor tweaks to LogEvents
Reviewed-by: kvn, twisti
This commit is contained in:
parent
e6f3ba89ec
commit
520f6fcc87
@ -204,7 +204,8 @@ class CompilationLog : public StringEventLog {
|
||||
}
|
||||
|
||||
void log_nmethod(JavaThread* thread, nmethod* nm) {
|
||||
log(thread, "nmethod " INTPTR_FORMAT " code ["INTPTR_FORMAT ", " INTPTR_FORMAT "]",
|
||||
log(thread, "nmethod %d%s " INTPTR_FORMAT " code ["INTPTR_FORMAT ", " INTPTR_FORMAT "]",
|
||||
nm->compile_id(), nm->is_osr_method() ? "%" : "",
|
||||
nm, nm->code_begin(), nm->code_end());
|
||||
}
|
||||
|
||||
|
@ -62,7 +62,7 @@ void GCHeapLog::log_heap(bool before) {
|
||||
return;
|
||||
}
|
||||
|
||||
jlong timestamp = os::javaTimeNanos() / NANOSECS_PER_MILLISEC;
|
||||
double timestamp = fetch_timestamp();
|
||||
MutexLockerEx ml(&_mutex, Mutex::_no_safepoint_check_flag);
|
||||
int index = compute_log_index();
|
||||
_records[index].thread = NULL; // Its the GC thread so it's not that interesting.
|
||||
@ -70,9 +70,9 @@ void GCHeapLog::log_heap(bool before) {
|
||||
_records[index].data.is_before = before;
|
||||
stringStream st(_records[index].data.buffer(), _records[index].data.size());
|
||||
if (before) {
|
||||
Universe::print_heap_before_gc(&st);
|
||||
Universe::print_heap_before_gc(&st, true);
|
||||
} else {
|
||||
Universe::print_heap_after_gc(&st);
|
||||
Universe::print_heap_after_gc(&st, true);
|
||||
}
|
||||
}
|
||||
|
||||
|
@ -31,7 +31,6 @@ volatile jint GC_locker::_jni_lock_count = 0;
|
||||
volatile jint GC_locker::_lock_count = 0;
|
||||
volatile bool GC_locker::_needs_gc = false;
|
||||
volatile bool GC_locker::_doing_gc = false;
|
||||
jlong GC_locker::_wait_begin = 0;
|
||||
|
||||
#ifdef ASSERT
|
||||
volatile jint GC_locker::_debug_jni_lock_count = 0;
|
||||
@ -69,9 +68,8 @@ bool GC_locker::check_active_before_gc() {
|
||||
_needs_gc = true;
|
||||
if (PrintJNIGCStalls && PrintGCDetails) {
|
||||
ResourceMark rm; // JavaThread::name() allocates to convert to UTF8
|
||||
_wait_begin = os::javaTimeNanos() / NANOSECS_PER_MILLISEC;
|
||||
gclog_or_tty->print_cr(INT64_FORMAT ": Setting _needs_gc. Thread \"%s\" %d locked.",
|
||||
_wait_begin, Thread::current()->name(), _jni_lock_count);
|
||||
gclog_or_tty->print_cr("%.3f: Setting _needs_gc. Thread \"%s\" %d locked.",
|
||||
gclog_or_tty->time_stamp().seconds(), Thread::current()->name(), _jni_lock_count);
|
||||
}
|
||||
|
||||
}
|
||||
@ -85,8 +83,8 @@ void GC_locker::stall_until_clear() {
|
||||
if (needs_gc()) {
|
||||
if (PrintJNIGCStalls && PrintGCDetails) {
|
||||
ResourceMark rm; // JavaThread::name() allocates to convert to UTF8
|
||||
gclog_or_tty->print_cr(INT64_FORMAT ": Allocation failed. Thread \"%s\" is stalled by JNI critical section, %d locked.",
|
||||
(os::javaTimeNanos() / NANOSECS_PER_MILLISEC) - _wait_begin, Thread::current()->name(), _jni_lock_count);
|
||||
gclog_or_tty->print_cr("%.3f: Allocation failed. Thread \"%s\" is stalled by JNI critical section, %d locked.",
|
||||
gclog_or_tty->time_stamp().seconds(), Thread::current()->name(), _jni_lock_count);
|
||||
}
|
||||
}
|
||||
|
||||
@ -131,8 +129,8 @@ void GC_locker::jni_unlock(JavaThread* thread) {
|
||||
MutexUnlocker munlock(JNICritical_lock);
|
||||
if (PrintJNIGCStalls && PrintGCDetails) {
|
||||
ResourceMark rm; // JavaThread::name() allocates to convert to UTF8
|
||||
gclog_or_tty->print_cr(INT64_FORMAT ": Thread \"%s\" is performing GC after exiting critical section, %d locked",
|
||||
(os::javaTimeNanos() / NANOSECS_PER_MILLISEC) - _wait_begin, Thread::current()->name(), _jni_lock_count);
|
||||
gclog_or_tty->print_cr("%.3f: Thread \"%s\" is performing GC after exiting critical section, %d locked",
|
||||
gclog_or_tty->time_stamp().seconds(), Thread::current()->name(), _jni_lock_count);
|
||||
}
|
||||
Universe::heap()->collect(GCCause::_gc_locker);
|
||||
}
|
||||
|
@ -63,9 +63,6 @@ class GC_locker: public AllStatic {
|
||||
// note: bool is typedef'd as jint
|
||||
static volatile bool _doing_gc; // unlock_critical() is doing a GC
|
||||
|
||||
static jlong _wait_begin; // Timestamp for the setting of _needs_gc.
|
||||
// Used only by printing code.
|
||||
|
||||
#ifdef ASSERT
|
||||
// This lock count is updated for all operations and is used to
|
||||
// validate the jni_lock_count that is computed during safepoints.
|
||||
|
@ -1303,22 +1303,22 @@ void Universe::print_heap_at_SIGBREAK() {
|
||||
}
|
||||
}
|
||||
|
||||
void Universe::print_heap_before_gc(outputStream* st) {
|
||||
void Universe::print_heap_before_gc(outputStream* st, bool ignore_extended) {
|
||||
st->print_cr("{Heap before GC invocations=%u (full %u):",
|
||||
heap()->total_collections(),
|
||||
heap()->total_full_collections());
|
||||
if (!PrintHeapAtGCExtended) {
|
||||
if (!PrintHeapAtGCExtended || ignore_extended) {
|
||||
heap()->print_on(st);
|
||||
} else {
|
||||
heap()->print_extended_on(st);
|
||||
}
|
||||
}
|
||||
|
||||
void Universe::print_heap_after_gc(outputStream* st) {
|
||||
void Universe::print_heap_after_gc(outputStream* st, bool ignore_extended) {
|
||||
st->print_cr("Heap after GC invocations=%u (full %u):",
|
||||
heap()->total_collections(),
|
||||
heap()->total_full_collections());
|
||||
if (!PrintHeapAtGCExtended) {
|
||||
if (!PrintHeapAtGCExtended || ignore_extended) {
|
||||
heap()->print_on(st);
|
||||
} else {
|
||||
heap()->print_extended_on(st);
|
||||
|
@ -424,8 +424,8 @@ class Universe: AllStatic {
|
||||
static void print_heap_at_SIGBREAK();
|
||||
static void print_heap_before_gc() { print_heap_before_gc(gclog_or_tty); }
|
||||
static void print_heap_after_gc() { print_heap_after_gc(gclog_or_tty); }
|
||||
static void print_heap_before_gc(outputStream* st);
|
||||
static void print_heap_after_gc(outputStream* st);
|
||||
static void print_heap_before_gc(outputStream* st, bool ignore_extended = false);
|
||||
static void print_heap_after_gc(outputStream* st, bool ignore_extended = false);
|
||||
|
||||
// Change the number of dummy objects kept reachable by the full gc dummy
|
||||
// array; this should trigger relocation in a sliding compaction collector.
|
||||
|
@ -804,6 +804,7 @@ address SharedRuntime::continuation_for_implicit_exception(JavaThread* thread,
|
||||
if (thread->deopt_mark() != NULL) {
|
||||
Deoptimization::cleanup_deopt_info(thread, NULL);
|
||||
}
|
||||
Events::log_exception(thread, "StackOverflowError at " INTPTR_FORMAT, pc);
|
||||
return StubRoutines::throw_StackOverflowError_entry();
|
||||
}
|
||||
|
||||
@ -820,8 +821,10 @@ address SharedRuntime::continuation_for_implicit_exception(JavaThread* thread,
|
||||
|
||||
if (vt_stub->is_abstract_method_error(pc)) {
|
||||
assert(!vt_stub->is_vtable_stub(), "should never see AbstractMethodErrors from vtable-type VtableStubs");
|
||||
Events::log_exception(thread, "AbstractMethodError at " INTPTR_FORMAT, pc);
|
||||
return StubRoutines::throw_AbstractMethodError_entry();
|
||||
} else {
|
||||
Events::log_exception(thread, "NullPointerException at vtable entry " INTPTR_FORMAT, pc);
|
||||
return StubRoutines::throw_NullPointerException_at_call_entry();
|
||||
}
|
||||
} else {
|
||||
@ -838,6 +841,7 @@ address SharedRuntime::continuation_for_implicit_exception(JavaThread* thread,
|
||||
if (!cb->is_nmethod()) {
|
||||
guarantee(cb->is_adapter_blob() || cb->is_method_handles_adapter_blob(),
|
||||
"exception happened outside interpreter, nmethods and vtable stubs (1)");
|
||||
Events::log_exception(thread, "NullPointerException in code blob at " INTPTR_FORMAT, pc);
|
||||
// There is no handler here, so we will simply unwind.
|
||||
return StubRoutines::throw_NullPointerException_at_call_entry();
|
||||
}
|
||||
@ -849,6 +853,7 @@ address SharedRuntime::continuation_for_implicit_exception(JavaThread* thread,
|
||||
// => the nmethod is not yet active (i.e., the frame
|
||||
// is not set up yet) => use return address pushed by
|
||||
// caller => don't push another return address
|
||||
Events::log_exception(thread, "NullPointerException in IC check " INTPTR_FORMAT, pc);
|
||||
return StubRoutines::throw_NullPointerException_at_call_entry();
|
||||
}
|
||||
|
||||
|
@ -600,6 +600,10 @@ extern "C" void flush() {
|
||||
tty->flush();
|
||||
}
|
||||
|
||||
extern "C" void events() {
|
||||
Command c("events");
|
||||
Events::print();
|
||||
}
|
||||
|
||||
// Given a heap address that was valid before the most recent GC, if
|
||||
// the oop that used to contain it is still live, prints the new
|
||||
@ -759,7 +763,7 @@ void help() {
|
||||
|
||||
tty->print_cr("misc.");
|
||||
tty->print_cr(" flush() - flushes the log file");
|
||||
tty->print_cr(" events() - dump last 50 events");
|
||||
tty->print_cr(" events() - dump events from ring buffers");
|
||||
|
||||
|
||||
tty->print_cr("compiler debugging");
|
||||
|
@ -68,6 +68,10 @@ void Events::print_all(outputStream* out) {
|
||||
}
|
||||
}
|
||||
|
||||
void Events::print() {
|
||||
print_all(tty);
|
||||
}
|
||||
|
||||
void Events::init() {
|
||||
if (LogEvents) {
|
||||
_messages = new StringEventLog("Events");
|
||||
|
@ -35,20 +35,12 @@
|
||||
// This facility is extremly useful for post-mortem debugging. The eventlog
|
||||
// often provides crucial information about events leading up to the crash.
|
||||
//
|
||||
// All arguments past the format string must be passed as an intptr_t.
|
||||
//
|
||||
// To log a single event use:
|
||||
// Events::log("New nmethod has been created " INTPTR_FORMAT, nm);
|
||||
//
|
||||
// To log a block of events use:
|
||||
// EventMark m("GarbageCollecting %d", (intptr_t)gc_number);
|
||||
//
|
||||
// The constructor to eventlog indents the eventlog until the
|
||||
// destructor has been executed.
|
||||
//
|
||||
// IMPLEMENTATION RESTRICTION:
|
||||
// Max 3 arguments are saved for each logged event.
|
||||
//
|
||||
// Abstractly the logs can record whatever they way but normally they
|
||||
// would record at least a timestamp and the current Thread, along
|
||||
// with whatever data they need in a ring buffer. Commonly fixed
|
||||
// length text messages are recorded for simplicity but other
|
||||
// strategies could be used. Several logs are provided by default but
|
||||
// new instances can be created as needed.
|
||||
|
||||
// The base event log dumping class that is registered for dumping at
|
||||
// crash time. This is a very generic interface that is mainly here
|
||||
@ -79,7 +71,7 @@ class EventLog : public CHeapObj {
|
||||
template <class T> class EventLogBase : public EventLog {
|
||||
template <class X> class EventRecord {
|
||||
public:
|
||||
jlong timestamp;
|
||||
double timestamp;
|
||||
Thread* thread;
|
||||
X data;
|
||||
};
|
||||
@ -102,6 +94,10 @@ template <class T> class EventLogBase : public EventLog {
|
||||
_records = new EventRecord<T>[length];
|
||||
}
|
||||
|
||||
double fetch_timestamp() {
|
||||
return tty->time_stamp().seconds();
|
||||
}
|
||||
|
||||
// move the ring buffer to next open slot and return the index of
|
||||
// the slot to use for the current message. Should only be called
|
||||
// while mutex is held.
|
||||
@ -130,7 +126,7 @@ template <class T> class EventLogBase : public EventLog {
|
||||
void print(outputStream* out, T& e);
|
||||
|
||||
void print(outputStream* out, EventRecord<T>& e) {
|
||||
out->print("Event: " INT64_FORMAT " ", e.timestamp);
|
||||
out->print("Event: %.3f ", e.timestamp);
|
||||
if (e.thread != NULL) {
|
||||
out->print("Thread " INTPTR_FORMAT " ", e.thread);
|
||||
}
|
||||
@ -155,7 +151,7 @@ class StringEventLog : public EventLogBase<StringLogMessage> {
|
||||
void logv(Thread* thread, const char* format, va_list ap) {
|
||||
if (!should_log()) return;
|
||||
|
||||
jlong timestamp = os::javaTimeNanos() / NANOSECS_PER_MILLISEC;
|
||||
double timestamp = fetch_timestamp();
|
||||
MutexLockerEx ml(&_mutex, Mutex::_no_safepoint_check_flag);
|
||||
int index = compute_log_index();
|
||||
_records[index].thread = thread;
|
||||
@ -193,9 +189,8 @@ class Events : AllStatic {
|
||||
public:
|
||||
static void print_all(outputStream* out);
|
||||
|
||||
static void print() {
|
||||
print_all(tty);
|
||||
}
|
||||
// Dump all events to the tty
|
||||
static void print();
|
||||
|
||||
// Logs a generic message with timestamp and format as printf.
|
||||
static void log(Thread* thread, const char* format, ...);
|
||||
@ -255,6 +250,7 @@ inline void EventLogBase<T>::print_log_impl(outputStream* out) {
|
||||
out->print_cr("%s (%d events):", _name, _count);
|
||||
if (_count == 0) {
|
||||
out->print_cr("No events");
|
||||
out->cr();
|
||||
return;
|
||||
}
|
||||
|
||||
|
Loading…
x
Reference in New Issue
Block a user