# HG changeset patch # User never # Date 1329329575 28800 # Node ID 09d00c18e323ffa6a04611347f5973b36eeea060 # Parent 80107dc493db42e7bf225a739158cedccad01bd1 7145537: minor tweaks to LogEvents Reviewed-by: kvn, twisti diff -r 80107dc493db -r 09d00c18e323 src/share/vm/compiler/compileBroker.cpp --- a/src/share/vm/compiler/compileBroker.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/compiler/compileBroker.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -204,7 +204,8 @@ } 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()); } diff -r 80107dc493db -r 09d00c18e323 src/share/vm/gc_interface/collectedHeap.cpp --- a/src/share/vm/gc_interface/collectedHeap.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/gc_interface/collectedHeap.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -62,7 +62,7 @@ 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 @@ _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); } } diff -r 80107dc493db -r 09d00c18e323 src/share/vm/memory/gcLocker.cpp --- a/src/share/vm/memory/gcLocker.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/memory/gcLocker.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -31,7 +31,6 @@ 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 @@ _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 @@ 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 @@ 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); } diff -r 80107dc493db -r 09d00c18e323 src/share/vm/memory/gcLocker.hpp --- a/src/share/vm/memory/gcLocker.hpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/memory/gcLocker.hpp Wed Feb 15 10:12:55 2012 -0800 @@ -63,9 +63,6 @@ // 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. diff -r 80107dc493db -r 09d00c18e323 src/share/vm/memory/universe.cpp --- a/src/share/vm/memory/universe.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/memory/universe.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -1303,22 +1303,22 @@ } } -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); diff -r 80107dc493db -r 09d00c18e323 src/share/vm/memory/universe.hpp --- a/src/share/vm/memory/universe.hpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/memory/universe.hpp Wed Feb 15 10:12:55 2012 -0800 @@ -424,8 +424,8 @@ 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. diff -r 80107dc493db -r 09d00c18e323 src/share/vm/runtime/sharedRuntime.cpp --- a/src/share/vm/runtime/sharedRuntime.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/runtime/sharedRuntime.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -804,6 +804,7 @@ 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 @@ 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 @@ 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 @@ // => 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(); } diff -r 80107dc493db -r 09d00c18e323 src/share/vm/utilities/debug.cpp --- a/src/share/vm/utilities/debug.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/utilities/debug.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -600,6 +600,10 @@ 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 @@ 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"); diff -r 80107dc493db -r 09d00c18e323 src/share/vm/utilities/events.cpp --- a/src/share/vm/utilities/events.cpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/utilities/events.cpp Wed Feb 15 10:12:55 2012 -0800 @@ -68,6 +68,10 @@ } } +void Events::print() { + print_all(tty); +} + void Events::init() { if (LogEvents) { _messages = new StringEventLog("Events"); diff -r 80107dc493db -r 09d00c18e323 src/share/vm/utilities/events.hpp --- a/src/share/vm/utilities/events.hpp Wed Feb 15 09:43:16 2012 +0100 +++ b/src/share/vm/utilities/events.hpp Wed Feb 15 10:12:55 2012 -0800 @@ -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 @@ template class EventLogBase : public EventLog { template class EventRecord { public: - jlong timestamp; + double timestamp; Thread* thread; X data; }; @@ -102,6 +94,10 @@ _records = new EventRecord[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 @@ void print(outputStream* out, T& e); void print(outputStream* out, EventRecord& 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 @@ 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 @@ 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 @@ out->print_cr("%s (%d events):", _name, _count); if (_count == 0) { out->print_cr("No events"); + out->cr(); return; }