--- a/hotspot/src/share/vm/compiler/compileBroker.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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());
}
--- a/hotspot/src/share/vm/gc_interface/collectedHeap.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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);
}
}
--- a/hotspot/src/share/vm/memory/gcLocker.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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);
}
--- a/hotspot/src/share/vm/memory/gcLocker.hpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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.
--- a/hotspot/src/share/vm/memory/universe.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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);
--- a/hotspot/src/share/vm/memory/universe.hpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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.
--- a/hotspot/src/share/vm/runtime/sharedRuntime.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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();
}
--- a/hotspot/src/share/vm/utilities/debug.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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");
--- a/hotspot/src/share/vm/utilities/events.cpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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");
--- a/hotspot/src/share/vm/utilities/events.hpp Wed Feb 15 09:43:16 2012 +0100
+++ b/hotspot/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 T> class EventLogBase : public EventLog {
template <class X> class EventRecord {
public:
- jlong timestamp;
+ double timestamp;
Thread* thread;
X data;
};
@@ -102,6 +94,10 @@
_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 @@
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 @@
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;
}