8149036: Add tracing for thread related events at os level
Reviewed-by: coleenp, mlarsson, dholmes
--- 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() {