# HG changeset patch # User dcubed # Date 1402613836 25200 # Node ID b13d25e6a193b6d16be8a5b00450916ef9e7943d # Parent fab862c73f1ce7c7dd959083eebbbbd5168ded5f 8046287: [TESTBUG] runtime/Thread/TestThreadDumpMonitorContention.java failed error_cnt=12 Summary: Added a new header waiting pattern to catch the case where the target thread waiting on a condition (like a VM op); several other test improvements Reviewed-by: sspitsyn, dholmes diff -r fab862c73f1c -r b13d25e6a193 hotspot/test/runtime/Thread/TestThreadDumpMonitorContention.java --- a/hotspot/test/runtime/Thread/TestThreadDumpMonitorContention.java Thu Jun 12 13:37:53 2014 -0400 +++ b/hotspot/test/runtime/Thread/TestThreadDumpMonitorContention.java Thu Jun 12 15:57:16 2014 -0700 @@ -24,6 +24,7 @@ /* * @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. * @@ -52,10 +53,13 @@ // 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_PATTERN = Pattern.compile( + 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 .*"); @@ -80,17 +84,34 @@ 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 String header_line = null; static boolean have_header_line = false; static boolean have_thread_state_line = false; - static int match_cnt = 0; - static String[] match_list = new String[2]; + 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) { @@ -110,6 +131,11 @@ 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) { } } @@ -118,8 +144,16 @@ Thread[] thread_list = new Thread[2]; thread_list[0] = new Thread(runnable, "ContendingThread-1"); thread_list[1] = new Thread(runnable, "ContendingThread-2"); - thread_list[0].start(); - thread_list[1].start(); + 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(); @@ -143,11 +177,12 @@ // 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:67) + // 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; @@ -161,49 +196,73 @@ // 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:67) + // 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:67) + // 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 + "'"); } - match_list[match_cnt] = new String(line); - match_cnt++; + locked_match_list[locked_line_match_cnt] = new String(line); + locked_line_match_cnt++; matcher = HEADER_RUNNABLE_PATTERN.matcher(header_line); - if (!matcher.matches()) { + if (matcher.matches()) { + sum_locked_hdr_runnable_cnt++; + } else { // It's strange, but a locked line can also - // match the HEADER_WAITING_PATTERN. - matcher = HEADER_WAITING_PATTERN.matcher(header_line); - if (!matcher.matches()) { - 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++; + // 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()) { + 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()) { + 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."); @@ -229,19 +288,22 @@ // 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:67) + // 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_PATTERN.matcher(header_line); - if (!matcher.matches()) { + 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."); @@ -251,7 +313,9 @@ } matcher = THREAD_STATE_BLOCKED_PATTERN.matcher(thread_state_line); - if (!matcher.matches()) { + 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."); @@ -273,7 +337,10 @@ static void doSamples() throws Exception { for (int count = 0; count < n_samples; count++) { - match_cnt = 0; + 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); @@ -290,12 +357,12 @@ // 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 + // 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_PATTERN + // - 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 @@ -324,6 +391,7 @@ 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 + "'"); @@ -366,19 +434,80 @@ } process.waitFor(); - if (match_cnt == 2) { - if (match_list[0].equals(match_list[1])) { - System.err.println(); - System.err.println("ERROR: matching lock lines:"); - System.err.println("ERROR: line[0]'" + match_list[0] + "'"); - System.err.println("ERROR: line[1]'" + match_list[1] + "'"); - error_cnt++; - } - } + 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