8150619: Improve thread based logging introduced with 8149036

Reviewed-by: coleenp, dholmes

hotspot/src/os/aix/vm/os_aix.cpp

@@ -1,6 +1,6 @@
 /*
- * Copyright (c) 1999, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1999, 2016, Oracle and/or its affiliates. All rights reserved.
- * Copyright (c) 2012, 2015 SAP SE. All rights reserved.
+ * Copyright (c) 2012, 2016 SAP SE. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -792,8 +792,8 @@ static void *java_start(Thread *thread) {
   const pthread_t pthread_id = ::pthread_self();
   const tid_t kernel_thread_id = ::thread_self();
 
-  log_info(os, thread)("Thread is alive (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ")",
+  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ", kernel thread id: " UINTX_FORMAT ").",
-    (uintx) pthread_id, (uintx) kernel_thread_id);
+    os::current_thread_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
@@ -801,7 +801,7 @@ static void *java_start(Thread *thread) {
   // guard pages on those stacks, because the stacks may reside in memory which is not
   // protectable (shmated).
   if (thread->stack_base() > ::sbrk(0)) {
-    log_warning(os, thread)("Thread " UINTX_FORMAT ": stack not in data segment.", (uintx)pthread_id);
+    log_warning(os, thread)("Thread stack not in data segment.");
   }
 
   // Try to randomize the cache line index of hot stack frames.
@@ -835,8 +835,8 @@ static void *java_start(Thread *thread) {
   // Call one more level start routine.
   thread->run();
 
-  log_info(os, thread)("Thread finished (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ").",
+  log_info(os, thread)("Thread finished (tid: " UINTX_FORMAT ", kernel thread id: " UINTX_FORMAT ").",
-    (uintx) pthread_id, (uintx) kernel_thread_id);
+    os::current_thread_id(), (uintx) kernel_thread_id);
 
   return 0;
 }
@@ -978,8 +978,8 @@ bool os::create_attached_thread(JavaThread* thread) {
   // 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 ")",
+  log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ", kernel thread id: " UINTX_FORMAT ").",
-    (uintx) pthread_id, (uintx) kernel_thread_id);
+    os::current_thread_id(), (uintx) kernel_thread_id);
 
   return true;
 }

hotspot/src/os/bsd/vm/os_bsd.cpp

@@ -682,7 +682,7 @@ static void *java_start(Thread *thread) {
 
   osthread->set_thread_id(os::Bsd::gettid());
 
-  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ".",
+  log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
     os::current_thread_id(), (uintx) pthread_self());
 
 #ifdef __APPLE__
@@ -720,7 +720,7 @@ static void *java_start(Thread *thread) {
   // call one more level start routine
   thread->run();
 
-  log_info(os, thread)("Thread finished (tid " UINTX_FORMAT ", pthread id " UINTX_FORMAT ").",
+  log_info(os, thread)("Thread finished (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
     os::current_thread_id(), (uintx) pthread_self());
 
   return 0;
@@ -871,7 +871,7 @@ bool os::create_attached_thread(JavaThread* thread) {
   // 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 ".",
+  log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
     os::current_thread_id(), (uintx) pthread_self());
 
   return true;

hotspot/src/os/linux/vm/os_linux.cpp

@@ -694,7 +694,7 @@ static void *java_start(Thread *thread) {
   // call one more level start routine
   thread->run();
 
-  log_info(os, thread)("Thread finished (tid " UINTX_FORMAT ", pthread id " UINTX_FORMAT ").",
+  log_info(os, thread)("Thread finished (tid: " UINTX_FORMAT ", pthread id: " UINTX_FORMAT ").",
     os::current_thread_id(), (uintx) pthread_self());
 
   return 0;

hotspot/src/os/solaris/vm/os_solaris.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 1997, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1997, 2016, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -891,12 +891,11 @@ bool os::create_main_thread(JavaThread* thread) {
 
 // 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)
+                                            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 PRINT_FLAG(f) if (flags & f) ss.print( #f " ");
   #define ALL(X) \
     X(THR_SUSPENDED) \
     X(THR_DETACHED) \
@@ -1006,7 +1005,7 @@ bool os::create_thread(Thread* thread, ThreadType thr_type,
 
   char buf[64];
   if (status == 0) {
-    log_info(os, thread)("Thread started (pthread id: " UINTX_FORMAT ", attributes: %s). ",
+    log_info(os, thread)("Thread started (tid: " 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.",

hotspot/src/os/windows/vm/os_windows.cpp

@@ -543,8 +543,7 @@ bool os::create_main_thread(JavaThread* thread) {
 // 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)
+                                               size_t stacksize, unsigned initflag) {
-{
   stringStream ss(buf, buflen);
   if (stacksize == 0) {
     ss.print("stacksize: default, ");
@@ -552,7 +551,7 @@ static char* describe_beginthreadex_attributes(char* buf, size_t buflen,
     ss.print("stacksize: " SIZE_FORMAT "k, ", stacksize / 1024);
   }
   ss.print("flags: ");
-  #define PRINT_FLAG(f) if (initflag & f) ss.print( XSTR(f) " ");
+  #define PRINT_FLAG(f) if (initflag & f) ss.print( #f " ");
   #define ALL(X) \
     X(CREATE_SUSPENDED) \
     X(STACK_SIZE_PARAM_IS_A_RESERVATION)

hotspot/src/share/vm/runtime/thread.cpp

@@ -1806,10 +1806,6 @@ void JavaThread::exit(bool destroy_vm, ExitType exit_type) {
     // 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.
@@ -1932,6 +1928,10 @@ void JavaThread::exit(bool destroy_vm, ExitType exit_type) {
   }
 #endif // INCLUDE_ALL_GCS
 
+  log_info(os, thread)("JavaThread %s (tid: " UINTX_FORMAT ").",
+    exit_type == JavaThread::normal_exit ? "exiting" : "detaching",
+    os::current_thread_id());
+
   // Remove from list of active threads list, and notify VM thread if we are the last non-daemon thread
   Threads::remove(this);
 }

hotspot/test/runtime/logging/ThreadLoggingTest.java

@@ -0,0 +1,69 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2016, SAP SE and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.    See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test
+ * @bug 8149036 8150619
+ * @summary os+thread output should contain logging calls for thread start stop attaches detaches
+ * @library /testlibrary
+ * @modules java.base/sun.misc
+ *          java.management
+ * @build jdk.test.lib.OutputAnalyzer jdk.test.lib.ProcessTools
+ * @run driver ThreadLoggingTest
+ * @author Thomas Stuefe (SAP)
+ */
+
+import java.io.File;
+import java.util.Map;
+import jdk.test.lib.OutputAnalyzer;
+import jdk.test.lib.ProcessTools;
+
+public class ThreadLoggingTest {
+
+    static void analyzeOutputForInfoLevel(OutputAnalyzer output) throws Exception {
+        output.shouldContain("Thread started");
+        output.shouldContain("Thread is alive");
+        output.shouldContain("Thread finished");
+        output.shouldHaveExitValue(0);
+    }
+
+    static void analyzeOutputForDebugLevel(OutputAnalyzer output) throws Exception {
+        analyzeOutputForInfoLevel(output);
+        output.shouldContain("stack dimensions");
+        output.shouldContain("stack guard pages");
+    }
+
+    public static void main(String[] args) throws Exception {
+
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:os+thread", "-version");
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        analyzeOutputForInfoLevel(output);
+
+        pb = ProcessTools.createJavaProcessBuilder("-Xlog:os+thread=debug", "-version");
+        output = new OutputAnalyzer(pb.start());
+        analyzeOutputForDebugLevel(output);
+
+    }
+
+}