7145537: minor tweaks to LogEvents

Reviewed-by: kvn, twisti

src/share/vm/compiler/compileBroker.cpp

@@ -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());
   }
 

src/share/vm/gc_interface/collectedHeap.cpp

@@ -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);
   }
 }
 

src/share/vm/memory/gcLocker.cpp

@@ -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);
       }

src/share/vm/memory/gcLocker.hpp

@@ -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.

src/share/vm/memory/universe.cpp

@@ -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);

src/share/vm/memory/universe.hpp

@@ -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.

src/share/vm/runtime/sharedRuntime.cpp

@@ -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();
           }
 

src/share/vm/utilities/debug.cpp

@@ -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");

src/share/vm/utilities/events.cpp

@@ -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");

src/share/vm/utilities/events.hpp

@@ -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;
   }