8149036: Add tracing for thread related events at os level
authorstuefe
Wed, 24 Feb 2016 18:06:34 +0100
changeset 36355 dd339cbafd31
parent 36353 28b633a6919d
child 36356 17e26d207802
8149036: Add tracing for thread related events at os level Reviewed-by: coleenp, mlarsson, dholmes
hotspot/src/os/aix/vm/os_aix.cpp
hotspot/src/os/bsd/vm/os_bsd.cpp
hotspot/src/os/linux/vm/os_linux.cpp
hotspot/src/os/posix/vm/os_posix.cpp
hotspot/src/os/posix/vm/os_posix.hpp
hotspot/src/os/solaris/vm/os_solaris.cpp
hotspot/src/os/windows/vm/os_windows.cpp
hotspot/src/share/vm/logging/logTag.hpp
hotspot/src/share/vm/runtime/thread.cpp
--- a/hotspot/src/os/aix/vm/os_aix.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/aix/vm/os_aix.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -36,6 +36,7 @@
 #include "compiler/compileBroker.hpp"
 #include "interpreter/interpreter.hpp"
 #include "jvm_aix.h"
+#include "logging/log.hpp"
 #include "libo4.hpp"
 #include "libperfstat_aix.hpp"
 #include "libodm_aix.hpp"
@@ -791,13 +792,8 @@
   const pthread_t pthread_id = ::pthread_self();
   const tid_t kernel_thread_id = ::thread_self();
 
-  trcVerbose("newborn Thread : pthread-id %u, ktid " UINT64_FORMAT
-    ", stack %p ... %p, stacksize 0x%IX (%IB)",
-    pthread_id, kernel_thread_id,
-    thread->stack_end(),
-    thread->stack_base(),
-    thread->stack_size(),
-    thread->stack_size());
+  log_info(os, thread)("Thread is alive (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ")",
+    (uintx) pthread_id, (uintx) kernel_thread_id);
 
   // Normally, pthread stacks on AIX live in the data segment (are allocated with malloc()
   // by the pthread library). In rare cases, this may not be the case, e.g. when third-party
@@ -805,7 +801,7 @@
   // guard pages on those stacks, because the stacks may reside in memory which is not
   // protectable (shmated).
   if (thread->stack_base() > ::sbrk(0)) {
-    trcVerbose("Thread " UINT64_FORMAT ": stack not in data segment.", (uint64_t) pthread_id);
+    log_warning(os, thread)("Thread " UINTX_FORMAT ": stack not in data segment.", (uintx)pthread_id);
   }
 
   // Try to randomize the cache line index of hot stack frames.
@@ -839,8 +835,8 @@
   // Call one more level start routine.
   thread->run();
 
-  trcVerbose("Thread finished : pthread-id %u, ktid " UINT64_FORMAT ".",
-    pthread_id, kernel_thread_id);
+  log_info(os, thread)("Thread finished (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ").",
+    (uintx) pthread_id, (uintx) kernel_thread_id);
 
   return 0;
 }
@@ -908,20 +904,19 @@
   pthread_t tid;
   int ret = pthread_create(&tid, &attr, (void* (*)(void*)) java_start, thread);
 
-  pthread_attr_destroy(&attr);
-
+
+  char buf[64];
   if (ret == 0) {
-    trcVerbose("Created New Thread : pthread-id %u", tid);
+    log_info(os, thread)("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+      (uintx) tid, os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
   } else {
-    if (os::Aix::on_pase()) {
-      // QIBM_MULTI_THREADED=Y is needed when the launcher is started on iSeries
-      // using QSH. Otherwise pthread_create fails with errno=11.
-      trcVerbose("(Please make sure you set the environment variable "
-              "QIBM_MULTI_THREADED=Y before running this program.)");
-    }
-    if (PrintMiscellaneous && (Verbose || WizardMode)) {
-      perror("pthread_create()");
-    }
+    log_warning(os, thread)("Failed to start thread - pthread_create failed (%s) for attributes: %s.",
+      strerror(ret), os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+  }
+
+  pthread_attr_destroy(&attr);
+
+  if (ret != 0) {
     // Need to clean up stuff we've allocated so far
     thread->set_osthread(NULL);
     delete osthread;
@@ -958,13 +953,6 @@
   const pthread_t pthread_id = ::pthread_self();
   const tid_t kernel_thread_id = ::thread_self();
 
-  trcVerbose("attaching Thread : pthread-id %u, ktid " UINT64_FORMAT ", stack %p ... %p, stacksize 0x%IX (%IB)",
-    pthread_id, kernel_thread_id,
-    thread->stack_end(),
-    thread->stack_base(),
-    thread->stack_size(),
-    thread->stack_size());
-
   // OSThread::thread_id is the pthread id.
   osthread->set_thread_id(pthread_id);
 
@@ -990,6 +978,9 @@
   // and save the caller's signal mask
   os::Aix::hotspot_sigmask(thread);
 
+  log_info(os, thread)("Thread attached (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ")",
+    (uintx) pthread_id, (uintx) kernel_thread_id);
+
   return true;
 }
 
--- a/hotspot/src/os/bsd/vm/os_bsd.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/bsd/vm/os_bsd.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -32,6 +32,7 @@
 #include "compiler/disassembler.hpp"
 #include "interpreter/interpreter.hpp"
 #include "jvm_bsd.h"
+#include "logging/log.hpp"
 #include "memory/allocation.inline.hpp"
 #include "memory/filemap.hpp"
 #include "mutex_bsd.inline.hpp"
@@ -681,6 +682,9 @@
 
   osthread->set_thread_id(os::Bsd::gettid());
 
+  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ".",
+    os::current_thread_id(), (uintx) pthread_self());
+
 #ifdef __APPLE__
   uint64_t unique_thread_id = locate_unique_thread_id(osthread->thread_id());
   guarantee(unique_thread_id != 0, "unique thread id was not found");
@@ -716,6 +720,9 @@
   // call one more level start routine
   thread->run();
 
+  log_info(os, thread)("Thread finished (tid " UINTX_FORMAT ", pthread id " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return 0;
 }
 
@@ -776,12 +783,18 @@
     pthread_t tid;
     int ret = pthread_create(&tid, &attr, (void* (*)(void*)) java_start, thread);
 
+    char buf[64];
+    if (ret == 0) {
+      log_info(os, thread)("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+        (uintx) tid, os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+    } else {
+      log_warning(os, thread)("Failed to start thread - pthread_create failed (%s) for attributes: %s.",
+        strerror(ret), os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+    }
+
     pthread_attr_destroy(&attr);
 
     if (ret != 0) {
-      if (PrintMiscellaneous && (Verbose || WizardMode)) {
-        perror("pthread_create()");
-      }
       // Need to clean up stuff we've allocated so far
       thread->set_osthread(NULL);
       delete osthread;
@@ -858,6 +871,9 @@
   // and save the caller's signal mask
   os::Bsd::hotspot_sigmask(thread);
 
+  log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ".",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return true;
 }
 
--- a/hotspot/src/os/linux/vm/os_linux.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/linux/vm/os_linux.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -662,6 +662,9 @@
 
   osthread->set_thread_id(os::current_thread_id());
 
+  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   if (UseNUMA) {
     int lgrp_id = os::numa_get_group_id();
     if (lgrp_id != -1) {
@@ -691,6 +694,9 @@
   // call one more level start routine
   thread->run();
 
+  log_info(os, thread)("Thread finished (tid " UINTX_FORMAT ", pthread id " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return 0;
 }
 
@@ -756,12 +762,18 @@
     pthread_t tid;
     int ret = pthread_create(&tid, &attr, (void* (*)(void*)) java_start, thread);
 
+    char buf[64];
+    if (ret == 0) {
+      log_info(os, thread)("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+        (uintx) tid, os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+    } else {
+      log_warning(os, thread)("Failed to start thread - pthread_create failed (%s) for attributes: %s.",
+        strerror(ret), os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+    }
+
     pthread_attr_destroy(&attr);
 
     if (ret != 0) {
-      if (PrintMiscellaneous && (Verbose || WizardMode)) {
-        perror("pthread_create()");
-      }
       // Need to clean up stuff we've allocated so far
       thread->set_osthread(NULL);
       delete osthread;
@@ -858,6 +870,9 @@
   // and save the caller's signal mask
   os::Linux::hotspot_sigmask(thread);
 
+  log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return true;
 }
 
--- a/hotspot/src/os/posix/vm/os_posix.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/posix/vm/os_posix.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -1071,6 +1071,19 @@
 #endif
 }
 
+char* os::Posix::describe_pthread_attr(char* buf, size_t buflen, const pthread_attr_t* attr) {
+  size_t stack_size = 0;
+  size_t guard_size = 0;
+  int detachstate = 0;
+  pthread_attr_getstacksize(attr, &stack_size);
+  pthread_attr_getguardsize(attr, &guard_size);
+  pthread_attr_getdetachstate(attr, &detachstate);
+  jio_snprintf(buf, buflen, "stacksize: " SIZE_FORMAT "k, guardsize: " SIZE_FORMAT "k, %s",
+    stack_size / 1024, guard_size / 1024,
+    (detachstate == PTHREAD_CREATE_DETACHED ? "detached" : "joinable"));
+  return buf;
+}
+
 
 os::WatcherThreadCrashProtection::WatcherThreadCrashProtection() {
   assert(Thread::current()->is_Watcher_thread(), "Must be WatcherThread");
--- a/hotspot/src/os/posix/vm/os_posix.hpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/posix/vm/os_posix.hpp	Wed Feb 24 18:06:34 2016 +0100
@@ -76,6 +76,11 @@
   static address ucontext_get_pc(const ucontext_t* ctx);
   // Set PC into context. Needed for continuation after signal.
   static void ucontext_set_pc(ucontext_t* ctx, address pc);
+
+  // Helper function; describes pthread attributes as short string. String is written
+  // to buf with len buflen; buf is returned.
+  static char* describe_pthread_attr(char* buf, size_t buflen, const pthread_attr_t* attr);
+
 };
 
 /*
--- a/hotspot/src/os/solaris/vm/os_solaris.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/solaris/vm/os_solaris.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -32,6 +32,7 @@
 #include "compiler/disassembler.hpp"
 #include "interpreter/interpreter.hpp"
 #include "jvm_solaris.h"
+#include "logging/log.hpp"
 #include "memory/allocation.inline.hpp"
 #include "memory/filemap.hpp"
 #include "mutex_solaris.inline.hpp"
@@ -68,6 +69,7 @@
 #include "utilities/defaultStream.hpp"
 #include "utilities/events.hpp"
 #include "utilities/growableArray.hpp"
+#include "utilities/macros.hpp"
 #include "utilities/vmError.hpp"
 
 // put OS-includes here
@@ -736,6 +738,9 @@
   osthr->set_lwp_id(_lwp_self());  // Store lwp in case we are bound
   thread->_schedctl = (void *) schedctl_init();
 
+  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ").",
+    os::current_thread_id());
+
   if (UseNUMA) {
     int lgrp_id = os::numa_get_group_id();
     if (lgrp_id != -1) {
@@ -781,6 +786,8 @@
     Atomic::dec(&os::Solaris::_os_thread_count);
   }
 
+  log_info(os, thread)("Thread finished (tid: " UINTX_FORMAT ").", os::current_thread_id());
+
   if (UseDetachedThreads) {
     thr_exit(NULL);
     ShouldNotReachHere();
@@ -853,6 +860,9 @@
   // and save the caller's signal mask
   os::Solaris::hotspot_sigmask(thread);
 
+  log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ").",
+    os::current_thread_id());
+
   return true;
 }
 
@@ -879,6 +889,25 @@
   return true;
 }
 
+// Helper function to trace thread attributes, similar to os::Posix::describe_pthread_attr()
+static char* describe_thr_create_attributes(char* buf, size_t buflen,
+  size_t stacksize, long flags)
+{
+  stringStream ss(buf, buflen);
+  ss.print("stacksize: " SIZE_FORMAT "k, ", stacksize / 1024);
+  ss.print("flags: ");
+  #define PRINT_FLAG(f) if (flags & f) ss.print( XSTR(f) " ");
+  #define ALL(X) \
+    X(THR_SUSPENDED) \
+    X(THR_DETACHED) \
+    X(THR_BOUND) \
+    X(THR_NEW_LWP) \
+    X(THR_DAEMON)
+  ALL(PRINT_FLAG)
+  #undef ALL
+  #undef PRINT_FLAG
+  return buf;
+}
 
 bool os::create_thread(Thread* thread, ThreadType thr_type,
                        size_t stack_size) {
@@ -974,10 +1003,17 @@
   osthread->set_thread_id(-1);
 
   status = thr_create(NULL, stack_size, java_start, thread, flags, &tid);
+
+  char buf[64];
+  if (status == 0) {
+    log_info(os, thread)("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+      (uintx) tid, describe_thr_create_attributes(buf, sizeof(buf), stack_size, flags));
+  } else {
+    log_warning(os, thread)("Failed to start thread - thr_create failed (%s) for attributes: %s.",
+      strerror(status), describe_thr_create_attributes(buf, sizeof(buf), stack_size, flags));
+  }
+
   if (status != 0) {
-    if (PrintMiscellaneous && (Verbose || WizardMode)) {
-      perror("os::create_thread");
-    }
     thread->set_osthread(NULL);
     // Need to clean up stuff we've allocated so far
     delete osthread;
--- a/hotspot/src/os/windows/vm/os_windows.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/os/windows/vm/os_windows.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -35,6 +35,7 @@
 #include "compiler/disassembler.hpp"
 #include "interpreter/interpreter.hpp"
 #include "jvm_windows.h"
+#include "logging/log.hpp"
 #include "memory/allocation.inline.hpp"
 #include "memory/filemap.hpp"
 #include "mutex_windows.inline.hpp"
@@ -71,6 +72,7 @@
 #include "utilities/defaultStream.hpp"
 #include "utilities/events.hpp"
 #include "utilities/growableArray.hpp"
+#include "utilities/macros.hpp"
 #include "utilities/vmError.hpp"
 
 #ifdef _DEBUG
@@ -436,6 +438,8 @@
     res = 20115;    // java thread
   }
 
+  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ").", os::current_thread_id());
+
   // Install a win32 structured exception handler around every thread created
   // by VM, so VM can generate error dump when an exception occurred in non-
   // Java thread (e.g. VM thread).
@@ -446,6 +450,8 @@
     // Nothing to do.
   }
 
+  log_info(os, thread)("Thread finished (tid: " UINTX_FORMAT ").", os::current_thread_id());
+
   // One less thread is executing
   // When the VMThread gets here, the main thread may have already exited
   // which frees the CodeHeap containing the Atomic::add code
@@ -509,6 +515,10 @@
   osthread->set_state(RUNNABLE);
 
   thread->set_osthread(osthread);
+
+  log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ").",
+    os::current_thread_id());
+
   return true;
 }
 
@@ -530,6 +540,28 @@
   return true;
 }
 
+// Helper function to trace _beginthreadex attributes,
+//  similar to os::Posix::describe_pthread_attr()
+static char* describe_beginthreadex_attributes(char* buf, size_t buflen,
+  size_t stacksize, unsigned initflag)
+{
+  stringStream ss(buf, buflen);
+  if (stacksize == 0) {
+    ss.print("stacksize: default, ");
+  } else {
+    ss.print("stacksize: " SIZE_FORMAT "k, ", stacksize / 1024);
+  }
+  ss.print("flags: ");
+  #define PRINT_FLAG(f) if (initflag & f) ss.print( XSTR(f) " ");
+  #define ALL(X) \
+    X(CREATE_SUSPENDED) \
+    X(STACK_SIZE_PARAM_IS_A_RESERVATION)
+  ALL(PRINT_FLAG)
+  #undef ALL
+  #undef PRINT_FLAG
+  return buf;
+}
+
 // Allocate and initialize a new OSThread
 bool os::create_thread(Thread* thread, ThreadType thr_type,
                        size_t stack_size) {
@@ -596,14 +628,24 @@
   // document because JVM uses C runtime library. The good news is that the
   // flag appears to work with _beginthredex() as well.
 
+  const unsigned initflag = CREATE_SUSPENDED | STACK_SIZE_PARAM_IS_A_RESERVATION;
   HANDLE thread_handle =
     (HANDLE)_beginthreadex(NULL,
                            (unsigned)stack_size,
                            (unsigned (__stdcall *)(void*)) java_start,
                            thread,
-                           CREATE_SUSPENDED | STACK_SIZE_PARAM_IS_A_RESERVATION,
+                           initflag,
                            &thread_id);
 
+  char buf[64];
+  if (thread_handle != NULL) {
+    log_info(os, thread)("Thread started (tid: %u, attributes: %s)",
+      thread_id, describe_beginthreadex_attributes(buf, sizeof(buf), stack_size, initflag));
+  } else {
+    log_warning(os, thread)("Failed to start thread - _beginthreadex failed (%s) for attributes: %s.",
+      strerror(errno), describe_beginthreadex_attributes(buf, sizeof(buf), stack_size, initflag));
+  }
+
   if (thread_handle == NULL) {
     // Need to clean up stuff we've allocated so far
     CloseHandle(osthread->interrupt_event());
--- a/hotspot/src/share/vm/logging/logTag.hpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/share/vm/logging/logTag.hpp	Wed Feb 24 18:06:34 2016 +0100
@@ -81,6 +81,7 @@
   LOG_TAG(survivor) \
   LOG_TAG(sweep) \
   LOG_TAG(task) \
+  LOG_TAG(thread) \
   LOG_TAG(tlab) \
   LOG_TAG(time) \
   LOG_TAG(verify) \
--- a/hotspot/src/share/vm/runtime/thread.cpp	Thu Feb 18 16:15:28 2016 +0100
+++ b/hotspot/src/share/vm/runtime/thread.cpp	Wed Feb 24 18:06:34 2016 +0100
@@ -324,6 +324,10 @@
   // record thread's native stack, stack grows downward
   MemTracker::record_thread_stack(stack_end(), stack_size());
 #endif // INCLUDE_NMT
+  log_debug(os, thread)("Thread " UINTX_FORMAT " stack dimensions: "
+    PTR_FORMAT "-" PTR_FORMAT " (" SIZE_FORMAT "k).",
+    os::current_thread_id(), p2i(stack_base() - stack_size()),
+    p2i(stack_base()), stack_size()/1024);
 }
 
 
@@ -1802,6 +1806,10 @@
     // Call after last event on thread
     EVENT_THREAD_EXIT(this);
 
+    log_info(os, thread)("Thread " UINTX_FORMAT " %s.",
+      os::current_thread_id(),
+      exit_type == JavaThread::normal_exit ? "exiting" : "detaching");
+
     // Call Thread.exit(). We try 3 times in case we got another Thread.stop during
     // the execution of the method. If that is not enough, then we don't really care. Thread.stop
     // is deprecated anyhow.
@@ -2491,18 +2499,25 @@
   // warning("Guarding at " PTR_FORMAT " for len " SIZE_FORMAT "\n", low_addr, len);
 
   if (allocate && !os::create_stack_guard_pages((char *) low_addr, len)) {
-    warning("Attempt to allocate stack guard pages failed.");
+    log_warning(os, thread)("Attempt to allocate stack guard pages failed.");
     return;
   }
 
   if (os::guard_memory((char *) low_addr, len)) {
     _stack_guard_state = stack_guard_enabled;
   } else {
-    warning("Attempt to protect stack guard pages failed.");
+    log_warning(os, thread)("Attempt to protect stack guard pages failed ("
+      PTR_FORMAT "-" PTR_FORMAT ").", p2i(low_addr), p2i(low_addr + len));
     if (os::uncommit_memory((char *) low_addr, len)) {
-      warning("Attempt to deallocate stack guard pages failed.");
+      log_warning(os, thread)("Attempt to deallocate stack guard pages failed.");
     }
+    return;
   }
+
+  log_debug(os, thread)("Thread " UINTX_FORMAT " stack guard pages activated: "
+    PTR_FORMAT "-" PTR_FORMAT ".",
+    os::current_thread_id(), p2i(low_addr), p2i(low_addr + len));
+
 }
 
 void JavaThread::remove_stack_guard_pages() {
@@ -2515,16 +2530,25 @@
     if (os::remove_stack_guard_pages((char *) low_addr, len)) {
       _stack_guard_state = stack_guard_unused;
     } else {
-      warning("Attempt to deallocate stack guard pages failed.");
+      log_warning(os, thread)("Attempt to deallocate stack guard pages failed ("
+        PTR_FORMAT "-" PTR_FORMAT ").", p2i(low_addr), p2i(low_addr + len));
+      return;
     }
   } else {
     if (_stack_guard_state == stack_guard_unused) return;
     if (os::unguard_memory((char *) low_addr, len)) {
       _stack_guard_state = stack_guard_unused;
     } else {
-      warning("Attempt to unprotect stack guard pages failed.");
+      log_warning(os, thread)("Attempt to unprotect stack guard pages failed ("
+        PTR_FORMAT "-" PTR_FORMAT ").", p2i(low_addr), p2i(low_addr + len));
+      return;
     }
   }
+
+  log_debug(os, thread)("Thread " UINTX_FORMAT " stack guard pages removed: "
+    PTR_FORMAT "-" PTR_FORMAT ".",
+    os::current_thread_id(), p2i(low_addr), p2i(low_addr + len));
+
 }
 
 void JavaThread::enable_stack_reserved_zone() {