# HG changeset patch
# User stuefe
# Date 1456301900 -3600
#      Wed Feb 24 09:18:20 2016 +0100
# Node ID 8e532e2a79557ef99f9b6fe3ff78883f51f32401
# Parent  1f58338cdec9946c16d2766d9801a9729858a997
8149036: Add tracing for thread related events at os level
Reviewed-by: coleenp, mlarsson

diff --git a/src/os/aix/vm/os_aix.cpp b/src/os/aix/vm/os_aix.cpp
--- a/src/os/aix/vm/os_aix.cpp
+++ b/src/os/aix/vm/os_aix.cpp
@@ -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_debug(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_debug(os, thread)("Thread finished (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ").",
+    (uintx) pthread_id, (uintx) kernel_thread_id);
 
   return 0;
 }
@@ -908,20 +904,21 @@
   pthread_t tid;
   int ret = pthread_create(&tid, &attr, (void* (*)(void*)) java_start, thread);
 
+  LogHandle(os, thread) log;
+  if (log.is_debug()) {
+    char buf[64];
+    if (ret == 0) {
+      log.debug("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+        (uintx) tid, os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+    } else {
+      log.warning("Failed to start thread - pthread_create failed (%s) for attributes: %s.",
+        strerror(errno), os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+    }
+  }
+
   pthread_attr_destroy(&attr);
 
-  if (ret == 0) {
-    trcVerbose("Created New Thread : pthread-id %u", tid);
-  } 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()");
-    }
+  if (ret != 0) {
     // Need to clean up stuff we've allocated so far
     thread->set_osthread(NULL);
     delete osthread;
@@ -958,13 +955,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 +980,9 @@
   // and save the caller's signal mask
   os::Aix::hotspot_sigmask(thread);
 
+  log_debug(os, thread)("Thread attached (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ")",
+    (uintx) pthread_id, (uintx) kernel_thread_id);
+
   return true;
 }
 
diff --git a/src/os/bsd/vm/os_bsd.cpp b/src/os/bsd/vm/os_bsd.cpp
--- a/src/os/bsd/vm/os_bsd.cpp
+++ b/src/os/bsd/vm/os_bsd.cpp
@@ -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_debug(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_debug(os, thread)("Thread finished (tid " UINTX_FORMAT ", pthread id " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return 0;
 }
 
@@ -776,12 +783,21 @@
     pthread_t tid;
     int ret = pthread_create(&tid, &attr, (void* (*)(void*)) java_start, thread);
 
+    LogHandle(os, thread) log;
+    if (log.is_debug()) {
+      char buf[64];
+      if (ret == 0) {
+        log.debug("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+          (uintx) tid, os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+      } else {
+        log.warning("Failed to start thread - pthread_create failed (%s) for attributes: %s.",
+          strerror(errno), 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 +874,9 @@
   // and save the caller's signal mask
   os::Bsd::hotspot_sigmask(thread);
 
+  log_debug(os, thread)("Thread attached (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ".",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return true;
 }
 
diff --git a/src/os/linux/vm/os_linux.cpp b/src/os/linux/vm/os_linux.cpp
--- a/src/os/linux/vm/os_linux.cpp
+++ b/src/os/linux/vm/os_linux.cpp
@@ -662,6 +662,9 @@
 
   osthread->set_thread_id(os::current_thread_id());
 
+  log_debug(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_debug(os, thread)("Thread finished (tid " UINTX_FORMAT ", pthread id " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return 0;
 }
 
@@ -756,12 +762,21 @@
     pthread_t tid;
     int ret = pthread_create(&tid, &attr, (void* (*)(void*)) java_start, thread);
 
+    LogHandle(os, thread) log;
+    if (log.is_debug()) {
+      char buf[64];
+      if (ret == 0) {
+        log.debug("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+          (uintx) tid, os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
+      } else {
+        log.warning("Failed to start thread - pthread_create failed (%s) for attributes: %s.",
+          strerror(errno), 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 +873,9 @@
   // and save the caller's signal mask
   os::Linux::hotspot_sigmask(thread);
 
+  log_debug(os, thread)("Thread attached (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
+    os::current_thread_id(), (uintx) pthread_self());
+
   return true;
 }
 
diff --git a/src/os/posix/vm/os_posix.cpp b/src/os/posix/vm/os_posix.cpp
--- a/src/os/posix/vm/os_posix.cpp
+++ b/src/os/posix/vm/os_posix.cpp
@@ -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");
diff --git a/src/os/posix/vm/os_posix.hpp b/src/os/posix/vm/os_posix.hpp
--- a/src/os/posix/vm/os_posix.hpp
+++ b/src/os/posix/vm/os_posix.hpp
@@ -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);
+
 };
 
 /*
diff --git a/src/os/solaris/vm/os_solaris.cpp b/src/os/solaris/vm/os_solaris.cpp
--- a/src/os/solaris/vm/os_solaris.cpp
+++ b/src/os/solaris/vm/os_solaris.cpp
@@ -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"
@@ -736,6 +737,9 @@
   osthr->set_lwp_id(_lwp_self());  // Store lwp in case we are bound
   thread->_schedctl = (void *) schedctl_init();
 
+  log_debug(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 +785,8 @@
     Atomic::dec(&os::Solaris::_os_thread_count);
   }
 
+  log_debug(os, thread)("Thread finished (tid: " UINTX_FORMAT ").", os::current_thread_id());
+
   if (UseDetachedThreads) {
     thr_exit(NULL);
     ShouldNotReachHere();
@@ -853,6 +859,9 @@
   // and save the caller's signal mask
   os::Solaris::hotspot_sigmask(thread);
 
+  log_debug(os, thread)("Thread attached (tid: " UINTX_FORMAT ").",
+    os::current_thread_id());
+
   return true;
 }
 
@@ -975,13 +984,14 @@
 
   status = thr_create(NULL, stack_size, java_start, thread, flags, &tid);
   if (status != 0) {
-    if (PrintMiscellaneous && (Verbose || WizardMode)) {
-      perror("os::create_thread");
-    }
+    log_warning(os, thread)("Failed to start thread - thr_create failed (%s)",
+      strerror(status));
     thread->set_osthread(NULL);
     // Need to clean up stuff we've allocated so far
     delete osthread;
     return false;
+  } else {
+    log_debug(os, thread)("Thread started (tid: " UINTX_FORMAT ").", (uintx) tid);
   }
 
   Atomic::inc(&os::Solaris::_os_thread_count);
diff --git a/src/os/windows/vm/os_windows.cpp b/src/os/windows/vm/os_windows.cpp
--- a/src/os/windows/vm/os_windows.cpp
+++ b/src/os/windows/vm/os_windows.cpp
@@ -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"
@@ -436,6 +437,8 @@
     res = 20115;    // java thread
   }
 
+  log_debug(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 +449,8 @@
     // Nothing to do.
   }
 
+  log_debug(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 +514,10 @@
   osthread->set_state(RUNNABLE);
 
   thread->set_osthread(osthread);
+
+  log_debug(os, thread)("Thread attached (tid: " UINTX_FORMAT ").",
+    os::current_thread_id());
+
   return true;
 }
 
@@ -605,11 +614,16 @@
                            &thread_id);
 
   if (thread_handle == NULL) {
+    log_warning(os, thread)("Failed to start thread - _beginthreadex failed (%s).",
+      strerror(errno));
+
     // Need to clean up stuff we've allocated so far
     CloseHandle(osthread->interrupt_event());
     thread->set_osthread(NULL);
     delete osthread;
     return NULL;
+  } else {
+    log_debug(os, thread)("Thread started (tid: %u)", thread_id);
   }
 
   Atomic::inc_ptr((intptr_t*)&os::win32::_os_thread_count);
diff --git a/src/share/vm/logging/logTag.hpp b/src/share/vm/logging/logTag.hpp
--- a/src/share/vm/logging/logTag.hpp
+++ b/src/share/vm/logging/logTag.hpp
@@ -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) \
diff --git a/src/share/vm/runtime/thread.cpp b/src/share/vm/runtime/thread.cpp
--- a/src/share/vm/runtime/thread.cpp
+++ b/src/share/vm/runtime/thread.cpp
@@ -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_debug(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() {