diff -r 000000000000 -r f90c822e73f8 test/runtime/Thread/TestThreadDumpMonitorContention.java --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/test/runtime/Thread/TestThreadDumpMonitorContention.java Wed Apr 27 01:25:04 2016 +0800 @@ -0,0 +1,534 @@ +/* + * Copyright (c) 2014, 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 + * 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 8036823 + * @bug 8046287 + * @summary Creates two threads contending for the same lock and checks + * whether jstack reports "locked" by more than one thread. + * + * @library /testlibrary + * @run main/othervm TestThreadDumpMonitorContention + */ + +import java.io.BufferedReader; +import java.io.InputStreamReader; +import java.lang.management.ManagementFactory; +import java.lang.management.RuntimeMXBean; +import java.util.ArrayList; +import java.util.List; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +import com.oracle.java.testlibrary.*; + +public class TestThreadDumpMonitorContention { + // jstack tends to be closely bound to the VM that we are running + // so use getTestJDKTool() instead of getCompileJDKTool() or even + // getJDKTool() which can fall back to "compile.jdk". + final static String JSTACK = JDKToolFinder.getTestJDKTool("jstack"); + final static String PID = getPid(); + + // looking for header lines with these patterns: + // "ContendingThread-1" #19 prio=5 os_prio=64 tid=0x000000000079c000 nid=0x23 runnable [0xffff80ffb8b87000] + // "ContendingThread-2" #21 prio=5 os_prio=64 tid=0x0000000000780000 nid=0x2f waiting for monitor entry [0xfffffd7fc1111000] + // "ContendingThread-2" #24 prio=5 os_prio=64 tid=0x0000000000ec8800 nid=0x31 waiting on condition [0xfffffd7bbfffe000] + final static Pattern HEADER_PREFIX_PATTERN = Pattern.compile( + "^\"ContendingThread-.*"); + final static Pattern HEADER_WAITING_PATTERN1 = Pattern.compile( + "^\"ContendingThread-.* waiting for monitor entry .*"); + final static Pattern HEADER_WAITING_PATTERN2 = Pattern.compile( + "^\"ContendingThread-.* waiting on condition .*"); + final static Pattern HEADER_RUNNABLE_PATTERN = Pattern.compile( + "^\"ContendingThread-.* runnable .*"); + + // looking for thread state lines with these patterns: + // java.lang.Thread.State: RUNNABLE + // java.lang.Thread.State: BLOCKED (on object monitor) + final static Pattern THREAD_STATE_PREFIX_PATTERN = Pattern.compile( + " *java\\.lang\\.Thread\\.State: .*"); + final static Pattern THREAD_STATE_BLOCKED_PATTERN = Pattern.compile( + " *java\\.lang\\.Thread\\.State: BLOCKED \\(on object monitor\\)"); + final static Pattern THREAD_STATE_RUNNABLE_PATTERN = Pattern.compile( + " *java\\.lang\\.Thread\\.State: RUNNABLE"); + + // looking for duplicates of this pattern: + // - locked <0x000000076ac59e20> (a TestThreadDumpMonitorContention$1) + final static Pattern LOCK_PATTERN = Pattern.compile( + ".* locked \\<.*\\(a TestThreadDumpMonitorContention.*"); + + // sanity checking header and thread state lines associated + // with this pattern: + // - waiting to lock <0x000000076ac59e20> (a TestThreadDumpMonitorContention$1) + final static Pattern WAITING_PATTERN = Pattern.compile( + ".* waiting to lock \\<.*\\(a TestThreadDumpMonitorContention.*"); + + final static Object barrier = new Object(); + volatile static boolean done = false; + + static int barrier_cnt = 0; + static int blank_line_match_cnt = 0; + static int error_cnt = 0; + static boolean have_header_line = false; + static boolean have_thread_state_line = false; + static String header_line = null; + static int header_prefix_match_cnt = 0; + static int locked_line_match_cnt = 0; + static String[] locked_match_list = new String[2]; + static int n_samples = 15; + static int sum_both_running_cnt = 0; + static int sum_both_waiting_cnt = 0; + static int sum_contended_cnt = 0; + static int sum_locked_hdr_runnable_cnt = 0; + static int sum_locked_hdr_waiting1_cnt = 0; + static int sum_locked_hdr_waiting2_cnt = 0; + static int sum_locked_thr_state_blocked_cnt = 0; + static int sum_locked_thr_state_runnable_cnt = 0; + static int sum_one_waiting_cnt = 0; + static int sum_uncontended_cnt = 0; + static int sum_waiting_hdr_waiting1_cnt = 0; + static int sum_waiting_thr_state_blocked_cnt = 0; + static String thread_state_line = null; + static boolean verbose = false; + static int waiting_line_match_cnt = 0; + + public static void main(String[] args) throws Exception { + if (args.length != 0) { + int arg_i = 0; + if (args[arg_i].equals("-v")) { + verbose = true; + arg_i++; + } + + try { + n_samples = Integer.parseInt(args[arg_i]); + } catch (NumberFormatException nfe) { + System.err.println(nfe); + usage(); + } + } + + Runnable runnable = new Runnable() { + public void run() { + synchronized (barrier) { + // let the main thread know we're running + barrier_cnt++; + barrier.notify(); + } + while (!done) { + synchronized (this) { } + } + } + }; + Thread[] thread_list = new Thread[2]; + thread_list[0] = new Thread(runnable, "ContendingThread-1"); + thread_list[1] = new Thread(runnable, "ContendingThread-2"); + synchronized (barrier) { + thread_list[0].start(); + thread_list[1].start(); + + // Wait until the contending threads are running so that + // we don't sample any thread init states. + while (barrier_cnt < 2) { + barrier.wait(); + } + } + + doSamples(); + + done = true; + + thread_list[0].join(); + thread_list[1].join(); + + if (error_cnt == 0) { + System.out.println("Test PASSED."); + } else { + System.out.println("Test FAILED."); + throw new AssertionError("error_cnt=" + error_cnt); + } + } + + // Reached a blank line which is the end of the + // stack trace without matching either LOCK_PATTERN + // or WAITING_PATTERN. Rare, but it's not an error. + // + // Example: + // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f runnable [0xfffffd7fc1111000] + // java.lang.Thread.State: RUNNABLE + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140) + // at java.lang.Thread.run(Thread.java:745) + // + static boolean checkBlankLine(String line) { + if (line.length() == 0) { + blank_line_match_cnt++; + have_header_line = false; + have_thread_state_line = false; + return true; + } + + return false; + } + + // Process the locked line here if we found one. + // + // Example 1: + // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f runnable [0xfffffd7fc1111000] + // java.lang.Thread.State: RUNNABLE + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140) + // - locked <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1) + // at java.lang.Thread.run(Thread.java:745) + // + // Example 2: + // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f waiting for monitor entry [0xfffffd7fc1111000] + // java.lang.Thread.State: BLOCKED (on object monitor) + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140) + // - locked <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1) + // at java.lang.Thread.run(Thread.java:745) + // + // Example 3: + // "ContendingThread-2" #24 prio=5 os_prio=64 tid=0x0000000000ec8800 nid=0x31 waiting on condition [0xfffffd7bbfffe000] + // java.lang.Thread.State: RUNNABLE + // JavaThread state: _thread_blocked + // Thread: 0x0000000000ec8800 [0x31] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 + // JavaThread state: _thread_blocked + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140) + // - locked <0xfffffd7e6d03eb28> (a TestThreadDumpMonitorContention$1) + // at java.lang.Thread.run(Thread.java:745) + // + static boolean checkLockedLine(String line) { + Matcher matcher = LOCK_PATTERN.matcher(line); + if (matcher.matches()) { + if (verbose) { + System.out.println("locked_line='" + line + "'"); + } + locked_match_list[locked_line_match_cnt] = new String(line); + locked_line_match_cnt++; + + matcher = HEADER_RUNNABLE_PATTERN.matcher(header_line); + if (matcher.matches()) { + sum_locked_hdr_runnable_cnt++; + } else { + // It's strange, but a locked line can also + // match the HEADER_WAITING_PATTERN{1,2}. + matcher = HEADER_WAITING_PATTERN1.matcher(header_line); + if (matcher.matches()) { + sum_locked_hdr_waiting1_cnt++; + } else { + matcher = HEADER_WAITING_PATTERN2.matcher(header_line); + if (matcher.matches()) { + sum_locked_hdr_waiting2_cnt++; + } else { + System.err.println(); + System.err.println("ERROR: header line does " + + "not match runnable or waiting patterns."); + System.err.println("ERROR: header_line='" + + header_line + "'"); + System.err.println("ERROR: locked_line='" + line + + "'"); + error_cnt++; + } + } + } + + matcher = THREAD_STATE_RUNNABLE_PATTERN.matcher(thread_state_line); + if (matcher.matches()) { + sum_locked_thr_state_runnable_cnt++; + } else { + // It's strange, but a locked line can also + // match the THREAD_STATE_BLOCKED_PATTERN. + matcher = THREAD_STATE_BLOCKED_PATTERN.matcher( + thread_state_line); + if (matcher.matches()) { + sum_locked_thr_state_blocked_cnt++; + } else { + System.err.println(); + System.err.println("ERROR: thread state line does not " + + "match runnable or waiting patterns."); + System.err.println("ERROR: " + "thread_state_line='" + + thread_state_line + "'"); + System.err.println("ERROR: locked_line='" + line + "'"); + error_cnt++; + } + } + + // Have everything we need from this thread stack + // that matches the LOCK_PATTERN. + have_header_line = false; + have_thread_state_line = false; + return true; + } + + return false; + } + + // Process the waiting line here if we found one. + // + // Example: + // "ContendingThread-2" #22 prio=5 os_prio=64 tid=0x00000000007b9800 nid=0x30 waiting for monitor entry [0xfffffd7fc1010000] + // java.lang.Thread.State: BLOCKED (on object monitor) + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140) + // - waiting to lock <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1) + // at java.lang.Thread.run(Thread.java:745) + // + static boolean checkWaitingLine(String line) { + Matcher matcher = WAITING_PATTERN.matcher(line); + if (matcher.matches()) { + waiting_line_match_cnt++; + if (verbose) { + System.out.println("waiting_line='" + line + "'"); + } + + matcher = HEADER_WAITING_PATTERN1.matcher(header_line); + if (matcher.matches()) { + sum_waiting_hdr_waiting1_cnt++; + } else { + System.err.println(); + System.err.println("ERROR: header line does " + + "not match a waiting pattern."); + System.err.println("ERROR: header_line='" + header_line + "'"); + System.err.println("ERROR: waiting_line='" + line + "'"); + error_cnt++; + } + + matcher = THREAD_STATE_BLOCKED_PATTERN.matcher(thread_state_line); + if (matcher.matches()) { + sum_waiting_thr_state_blocked_cnt++; + } else { + System.err.println(); + System.err.println("ERROR: thread state line " + + "does not match a waiting pattern."); + System.err.println("ERROR: thread_state_line='" + + thread_state_line + "'"); + System.err.println("ERROR: waiting_line='" + line + "'"); + error_cnt++; + } + + // Have everything we need from this thread stack + // that matches the WAITING_PATTERN. + have_header_line = false; + have_thread_state_line = false; + return true; + } + + return false; + } + + static void doSamples() throws Exception { + for (int count = 0; count < n_samples; count++) { + blank_line_match_cnt = 0; + header_prefix_match_cnt = 0; + locked_line_match_cnt = 0; + waiting_line_match_cnt = 0; + // verbose mode or an error has a lot of output so add more space + if (verbose || error_cnt > 0) System.out.println(); + System.out.println("Sample #" + count); + + // We don't use the ProcessTools, OutputBuffer or + // OutputAnalyzer classes from the testlibrary because + // we have a complicated multi-line parse to perform + // on a narrow subset of the JSTACK output. + // + // - we only care about stack traces that match + // HEADER_PREFIX_PATTERN; only two should match + // - we care about at most three lines from each stack trace + // - if both stack traces match LOCKED_PATTERN, then that's + // a failure and we report it + // - for a stack trace that matches LOCKED_PATTERN, we verify: + // - the header line matches HEADER_RUNNABLE_PATTERN + // or HEADER_WAITING_PATTERN{1,2} + // - the thread state line matches THREAD_STATE_BLOCKED_PATTERN + // or THREAD_STATE_RUNNABLE_PATTERN + // - we report any mismatches as failures + // - for a stack trace that matches WAITING_PATTERN, we verify: + // - the header line matches HEADER_WAITING_PATTERN1 + // - the thread state line matches THREAD_STATE_BLOCKED_PATTERN + // - we report any mismatches as failures + // - the stack traces that match HEADER_PREFIX_PATTERN may + // not match either LOCKED_PATTERN or WAITING_PATTERN + // because we might observe the thread outside of + // monitor operations; this is not considered a failure + // + // When we do observe LOCKED_PATTERN or WAITING_PATTERN, + // then we are checking the header and thread state patterns + // that occurred earlier in the current stack trace that + // matched HEADER_PREFIX_PATTERN. We don't use data from + // stack traces that don't match HEADER_PREFIX_PATTERN and + // we don't mix data between the two stack traces that do + // match HEADER_PREFIX_PATTERN. + // + Process process = new ProcessBuilder(JSTACK, PID) + .redirectErrorStream(true).start(); + + BufferedReader reader = new BufferedReader(new InputStreamReader( + process.getInputStream())); + String line; + while ((line = reader.readLine()) != null) { + Matcher matcher = null; + + // process the header line here + if (!have_header_line) { + matcher = HEADER_PREFIX_PATTERN.matcher(line); + if (matcher.matches()) { + header_prefix_match_cnt++; + if (verbose) { + System.out.println(); + System.out.println("header='" + line + "'"); + } + header_line = new String(line); + have_header_line = true; + continue; + } + continue; // skip until have a header line + } + + // process the thread state line here + if (!have_thread_state_line) { + matcher = THREAD_STATE_PREFIX_PATTERN.matcher(line); + if (matcher.matches()) { + if (verbose) { + System.out.println("thread_state='" + line + "'"); + } + thread_state_line = new String(line); + have_thread_state_line = true; + continue; + } + continue; // skip until we have a thread state line + } + + // process the locked line here if we find one + if (checkLockedLine(line)) { + continue; + } + + // process the waiting line here if we find one + if (checkWaitingLine(line)) { + continue; + } + + // process the blank line here if we find one + if (checkBlankLine(line)) { + continue; + } + } + process.waitFor(); + + if (header_prefix_match_cnt != 2) { + System.err.println(); + System.err.println("ERROR: should match exactly two headers."); + System.err.println("ERROR: header_prefix_match_cnt=" + + header_prefix_match_cnt); + error_cnt++; + } + + if (locked_line_match_cnt == 2) { + if (locked_match_list[0].equals(locked_match_list[1])) { + System.err.println(); + System.err.println("ERROR: matching lock lines:"); + System.err.println("ERROR: line[0]'" + + locked_match_list[0] + "'"); + System.err.println("ERROR: line[1]'" + + locked_match_list[1] + "'"); + error_cnt++; + } + } + + if (locked_line_match_cnt == 1) { + // one thread has the lock + if (waiting_line_match_cnt == 1) { + // and the other contended for it + sum_contended_cnt++; + } else { + // and the other is just running + sum_uncontended_cnt++; + } + } else if (waiting_line_match_cnt == 1) { + // one thread is waiting + sum_one_waiting_cnt++; + } else if (waiting_line_match_cnt == 2) { + // both threads are waiting + sum_both_waiting_cnt++; + } else { + // both threads are running + sum_both_running_cnt++; + } + + // slight delay between jstack launches + Thread.sleep(500); + } + + if (error_cnt != 0) { + // skip summary info since there were errors + return; + } + + System.out.println("INFO: Summary for all samples:"); + System.out.println("INFO: both_running_cnt=" + sum_both_running_cnt); + System.out.println("INFO: both_waiting_cnt=" + sum_both_waiting_cnt); + System.out.println("INFO: contended_cnt=" + sum_contended_cnt); + System.out.println("INFO: one_waiting_cnt=" + sum_one_waiting_cnt); + System.out.println("INFO: uncontended_cnt=" + sum_uncontended_cnt); + System.out.println("INFO: locked_hdr_runnable_cnt=" + + sum_locked_hdr_runnable_cnt); + System.out.println("INFO: locked_hdr_waiting1_cnt=" + + sum_locked_hdr_waiting1_cnt); + System.out.println("INFO: locked_hdr_waiting2_cnt=" + + sum_locked_hdr_waiting2_cnt); + System.out.println("INFO: locked_thr_state_blocked_cnt=" + + sum_locked_thr_state_blocked_cnt); + System.out.println("INFO: locked_thr_state_runnable_cnt=" + + sum_locked_thr_state_runnable_cnt); + System.out.println("INFO: waiting_hdr_waiting1_cnt=" + + sum_waiting_hdr_waiting1_cnt); + System.out.println("INFO: waiting_thr_state_blocked_cnt=" + + sum_waiting_thr_state_blocked_cnt); + + if (sum_contended_cnt == 0) { + System.err.println("WARNING: the primary scenario for 8036823" + + " has not been exercised by this test run."); + } + } + + // This helper relies on RuntimeMXBean.getName() returning a string + // that looks like this: 5436@mt-haku + // + // The testlibrary has tryFindJvmPid(), but that uses a separate + // process which is much more expensive for finding out your own PID. + // + static String getPid() { + RuntimeMXBean runtimebean = ManagementFactory.getRuntimeMXBean(); + String vmname = runtimebean.getName(); + int i = vmname.indexOf('@'); + if (i != -1) { + vmname = vmname.substring(0, i); + } + return vmname; + } + + static void usage() { + System.err.println("Usage: " + + "java TestThreadDumpMonitorContention [-v] [n_samples]"); + System.exit(1); + } +}