# HG changeset patch # User stuefe # Date 1456732257 -3600 # Mon Feb 29 08:50:57 2016 +0100 # Node ID f0ecdcac84c1e7fd5afc4ce8efab4feec3a9cf4d # Parent 69f183dacdb48c71006c37335253173198776551 8150619: Improve thread based logging introduced with 8149036 Reviewed-by: 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 @@ -1,6 +1,6 @@ /* - * Copyright (c) 1999, 2015, Oracle and/or its affiliates. All rights reserved. - * Copyright (c) 2012, 2015 SAP SE. All rights reserved. + * Copyright (c) 1999, 2016, Oracle and/or its affiliates. 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 @@ 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 ")", - (uintx) pthread_id, (uintx) kernel_thread_id); + log_info(os, thread)("Thread is alive (tid: " UINTX_FORMAT ", kernel thread id: " UINTX_FORMAT ").", + 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 @@ // 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 @@ // Call one more level start routine. thread->run(); - log_info(os, thread)("Thread finished (pthread id " UINTX_FORMAT ", tid " UINTX_FORMAT ").", - (uintx) pthread_id, (uintx) kernel_thread_id); + log_info(os, thread)("Thread finished (tid: " UINTX_FORMAT ", kernel thread id: " UINTX_FORMAT ").", + os::current_thread_id(), (uintx) kernel_thread_id); return 0; } @@ -978,8 +978,8 @@ // 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); + log_info(os, thread)("Thread attached (tid: " UINTX_FORMAT ", kernel thread id: " UINTX_FORMAT ").", + os::current_thread_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 @@ -682,7 +682,7 @@ 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 @@ // 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 @@ // 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; 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 @@ -694,7 +694,7 @@ // 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; 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 @@ -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 @@ // 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 @@ 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.", 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 @@ -543,8 +543,7 @@ // 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 @@ 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) 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 @@ -1806,10 +1806,6 @@ // 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 @@ } #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); } diff --git a/test/runtime/logging/ThreadLoggingTest.java b/test/runtime/logging/ThreadLoggingTest.java new file mode 100644 --- /dev/null +++ b/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); + + } + +}