8046287: [TESTBUG] runtime/Thread/TestThreadDumpMonitorContention.java failed error_cnt=12
authordcubed
Thu, 12 Jun 2014 15:57:16 -0700
changeset 25061 b13d25e6a193
parent 25060 fab862c73f1c
child 25062 d38c0d15b3f7
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
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