Wed, 04 Jun 2014 06:25:53 -0700
8036823: Stack trace sometimes shows 'locked' instead of 'waiting to lock'
Summary: Add a !owner check for 'waiting to lock' to catch current_pending_monitor corner cases.
Reviewed-by: dholmes, sspitsyn, kmo, zgu
Contributed-by: rednaxelafx@gmail.com, zhengyu.gu@oracle.com, daniel.daugherty@oracle.com
1.1 --- a/src/share/vm/runtime/objectMonitor.cpp Fri May 30 10:43:51 2014 +0200 1.2 +++ b/src/share/vm/runtime/objectMonitor.cpp Wed Jun 04 06:25:53 2014 -0700 1.3 @@ -418,6 +418,15 @@ 1.4 jt->java_suspend_self(); 1.5 } 1.6 Self->set_current_pending_monitor(NULL); 1.7 + 1.8 + // We cleared the pending monitor info since we've just gotten past 1.9 + // the enter-check-for-suspend dance and we now own the monitor free 1.10 + // and clear, i.e., it is no longer pending. The ThreadBlockInVM 1.11 + // destructor can go to a safepoint at the end of this block. If we 1.12 + // do a thread dump during that safepoint, then this thread will show 1.13 + // as having "-locked" the monitor, but the OS and java.lang.Thread 1.14 + // states will still report that the thread is blocked trying to 1.15 + // acquire it. 1.16 } 1.17 1.18 Atomic::dec_ptr(&_count);
2.1 --- a/src/share/vm/runtime/vframe.cpp Fri May 30 10:43:51 2014 +0200 2.2 +++ b/src/share/vm/runtime/vframe.cpp Wed Jun 04 06:25:53 2014 -0700 2.3 @@ -199,6 +199,7 @@ 2.4 continue; 2.5 } 2.6 if (monitor->owner() != NULL) { 2.7 + // the monitor is associated with an object, i.e., it is locked 2.8 2.9 // First, assume we have the monitor locked. If we haven't found an 2.10 // owned monitor before and this is the first frame, then we need to 2.11 @@ -209,7 +210,11 @@ 2.12 if (!found_first_monitor && frame_count == 0) { 2.13 markOop mark = monitor->owner()->mark(); 2.14 if (mark->has_monitor() && 2.15 - mark->monitor() == thread()->current_pending_monitor()) { 2.16 + ( // we have marked ourself as pending on this monitor 2.17 + mark->monitor() == thread()->current_pending_monitor() || 2.18 + // we are not the owner of this monitor 2.19 + !mark->monitor()->is_entered(thread()) 2.20 + )) { 2.21 lock_state = "waiting to lock"; 2.22 } 2.23 }
3.1 --- a/test/TEST.groups Fri May 30 10:43:51 2014 +0200 3.2 +++ b/test/TEST.groups Wed Jun 04 06:25:53 2014 -0700 3.3 @@ -1,5 +1,5 @@ 3.4 # 3.5 -# Copyright (c) 2013, Oracle and/or its affiliates. All rights reserved. 3.6 +# Copyright (c) 2013, 2014, Oracle and/or its affiliates. All rights reserved. 3.7 # DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 3.8 # 3.9 # This code is free software; you can redistribute it and/or modify it 3.10 @@ -84,6 +84,7 @@ 3.11 runtime/NMT/ThreadedVirtualAllocTestType.java \ 3.12 runtime/NMT/VirtualAllocTestType.java \ 3.13 runtime/RedefineObject/TestRedefineObject.java \ 3.14 + runtime/Thread/TestThreadDumpMonitorContention.java \ 3.15 runtime/XCheckJniJsig/XCheckJSig.java \ 3.16 serviceability/attach/AttachWithStalePidFile.java \ 3.17 serviceability/sa/jmap-hprof/JMapHProfLargeHeapTest.java
4.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000 4.2 +++ b/test/runtime/Thread/TestThreadDumpMonitorContention.java Wed Jun 04 06:25:53 2014 -0700 4.3 @@ -0,0 +1,405 @@ 4.4 +/* 4.5 + * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. 4.6 + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 4.7 + * 4.8 + * This code is free software; you can redistribute it and/or modify it 4.9 + * under the terms of the GNU General Public License version 2 only, as 4.10 + * published by the Free Software Foundation. 4.11 + * 4.12 + * This code is distributed in the hope that it will be useful, but WITHOUT 4.13 + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 4.14 + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 4.15 + * version 2 for more details (a copy is included in the LICENSE file that 4.16 + * accompanied this code). 4.17 + * 4.18 + * You should have received a copy of the GNU General Public License version 4.19 + * 2 along with this work; if not, write to the Free Software Foundation, 4.20 + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 4.21 + * 4.22 + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 4.23 + * or visit www.oracle.com if you need additional information or have any 4.24 + * questions. 4.25 + */ 4.26 + 4.27 +/* 4.28 + * @test 4.29 + * @bug 8036823 4.30 + * @summary Creates two threads contending for the same lock and checks 4.31 + * whether jstack reports "locked" by more than one thread. 4.32 + * 4.33 + * @library /testlibrary 4.34 + * @run main/othervm TestThreadDumpMonitorContention 4.35 + */ 4.36 + 4.37 +import java.io.BufferedReader; 4.38 +import java.io.InputStreamReader; 4.39 +import java.lang.management.ManagementFactory; 4.40 +import java.lang.management.RuntimeMXBean; 4.41 +import java.util.ArrayList; 4.42 +import java.util.List; 4.43 +import java.util.regex.Matcher; 4.44 +import java.util.regex.Pattern; 4.45 + 4.46 +import com.oracle.java.testlibrary.*; 4.47 + 4.48 +public class TestThreadDumpMonitorContention { 4.49 + // jstack tends to be closely bound to the VM that we are running 4.50 + // so use getTestJDKTool() instead of getCompileJDKTool() or even 4.51 + // getJDKTool() which can fall back to "compile.jdk". 4.52 + final static String JSTACK = JDKToolFinder.getTestJDKTool("jstack"); 4.53 + final static String PID = getPid(); 4.54 + 4.55 + // looking for header lines with these patterns: 4.56 + // "ContendingThread-1" #19 prio=5 os_prio=64 tid=0x000000000079c000 nid=0x23 runnable [0xffff80ffb8b87000] 4.57 + // "ContendingThread-2" #21 prio=5 os_prio=64 tid=0x0000000000780000 nid=0x2f waiting for monitor entry [0xfffffd7fc1111000] 4.58 + final static Pattern HEADER_PREFIX_PATTERN = Pattern.compile( 4.59 + "^\"ContendingThread-.*"); 4.60 + final static Pattern HEADER_WAITING_PATTERN = Pattern.compile( 4.61 + "^\"ContendingThread-.* waiting for monitor entry .*"); 4.62 + final static Pattern HEADER_RUNNABLE_PATTERN = Pattern.compile( 4.63 + "^\"ContendingThread-.* runnable .*"); 4.64 + 4.65 + // looking for thread state lines with these patterns: 4.66 + // java.lang.Thread.State: RUNNABLE 4.67 + // java.lang.Thread.State: BLOCKED (on object monitor) 4.68 + final static Pattern THREAD_STATE_PREFIX_PATTERN = Pattern.compile( 4.69 + " *java\\.lang\\.Thread\\.State: .*"); 4.70 + final static Pattern THREAD_STATE_BLOCKED_PATTERN = Pattern.compile( 4.71 + " *java\\.lang\\.Thread\\.State: BLOCKED \\(on object monitor\\)"); 4.72 + final static Pattern THREAD_STATE_RUNNABLE_PATTERN = Pattern.compile( 4.73 + " *java\\.lang\\.Thread\\.State: RUNNABLE"); 4.74 + 4.75 + // looking for duplicates of this pattern: 4.76 + // - locked <0x000000076ac59e20> (a TestThreadDumpMonitorContention$1) 4.77 + final static Pattern LOCK_PATTERN = Pattern.compile( 4.78 + ".* locked \\<.*\\(a TestThreadDumpMonitorContention.*"); 4.79 + 4.80 + // sanity checking header and thread state lines associated 4.81 + // with this pattern: 4.82 + // - waiting to lock <0x000000076ac59e20> (a TestThreadDumpMonitorContention$1) 4.83 + final static Pattern WAITING_PATTERN = Pattern.compile( 4.84 + ".* waiting to lock \\<.*\\(a TestThreadDumpMonitorContention.*"); 4.85 + 4.86 + volatile static boolean done = false; 4.87 + 4.88 + static int error_cnt = 0; 4.89 + static String header_line = null; 4.90 + static boolean have_header_line = false; 4.91 + static boolean have_thread_state_line = false; 4.92 + static int match_cnt = 0; 4.93 + static String[] match_list = new String[2]; 4.94 + static int n_samples = 15; 4.95 + static String thread_state_line = null; 4.96 + static boolean verbose = false; 4.97 + 4.98 + public static void main(String[] args) throws Exception { 4.99 + if (args.length != 0) { 4.100 + int arg_i = 0; 4.101 + if (args[arg_i].equals("-v")) { 4.102 + verbose = true; 4.103 + arg_i++; 4.104 + } 4.105 + 4.106 + try { 4.107 + n_samples = Integer.parseInt(args[arg_i]); 4.108 + } catch (NumberFormatException nfe) { 4.109 + System.err.println(nfe); 4.110 + usage(); 4.111 + } 4.112 + } 4.113 + 4.114 + Runnable runnable = new Runnable() { 4.115 + public void run() { 4.116 + while (!done) { 4.117 + synchronized (this) { } 4.118 + } 4.119 + } 4.120 + }; 4.121 + Thread[] thread_list = new Thread[2]; 4.122 + thread_list[0] = new Thread(runnable, "ContendingThread-1"); 4.123 + thread_list[1] = new Thread(runnable, "ContendingThread-2"); 4.124 + thread_list[0].start(); 4.125 + thread_list[1].start(); 4.126 + 4.127 + doSamples(); 4.128 + 4.129 + done = true; 4.130 + 4.131 + thread_list[0].join(); 4.132 + thread_list[1].join(); 4.133 + 4.134 + if (error_cnt == 0) { 4.135 + System.out.println("Test PASSED."); 4.136 + } else { 4.137 + System.out.println("Test FAILED."); 4.138 + throw new AssertionError("error_cnt=" + error_cnt); 4.139 + } 4.140 + } 4.141 + 4.142 + // Reached a blank line which is the end of the 4.143 + // stack trace without matching either LOCK_PATTERN 4.144 + // or WAITING_PATTERN. Rare, but it's not an error. 4.145 + // 4.146 + // Example: 4.147 + // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f runnable [0xfffffd7fc1111000] 4.148 + // java.lang.Thread.State: RUNNABLE 4.149 + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:67) 4.150 + // at java.lang.Thread.run(Thread.java:745) 4.151 + // 4.152 + static boolean checkBlankLine(String line) { 4.153 + if (line.length() == 0) { 4.154 + have_header_line = false; 4.155 + have_thread_state_line = false; 4.156 + return true; 4.157 + } 4.158 + 4.159 + return false; 4.160 + } 4.161 + 4.162 + // Process the locked line here if we found one. 4.163 + // 4.164 + // Example 1: 4.165 + // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f runnable [0xfffffd7fc1111000] 4.166 + // java.lang.Thread.State: RUNNABLE 4.167 + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:67) 4.168 + // - locked <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1) 4.169 + // at java.lang.Thread.run(Thread.java:745) 4.170 + // 4.171 + // Example 2: 4.172 + // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f waiting for monitor entry [0xfffffd7fc1111000] 4.173 + // java.lang.Thread.State: BLOCKED (on object monitor) 4.174 + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:67) 4.175 + // - locked <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1) 4.176 + // at java.lang.Thread.run(Thread.java:745) 4.177 + // 4.178 + static boolean checkLockedLine(String line) { 4.179 + Matcher matcher = LOCK_PATTERN.matcher(line); 4.180 + if (matcher.matches()) { 4.181 + if (verbose) { 4.182 + System.out.println("locked_line='" + line + "'"); 4.183 + } 4.184 + match_list[match_cnt] = new String(line); 4.185 + match_cnt++; 4.186 + 4.187 + matcher = HEADER_RUNNABLE_PATTERN.matcher(header_line); 4.188 + if (!matcher.matches()) { 4.189 + // It's strange, but a locked line can also 4.190 + // match the HEADER_WAITING_PATTERN. 4.191 + matcher = HEADER_WAITING_PATTERN.matcher(header_line); 4.192 + if (!matcher.matches()) { 4.193 + System.err.println(); 4.194 + System.err.println("ERROR: header line does " + 4.195 + "not match runnable or waiting patterns."); 4.196 + System.err.println("ERROR: header_line='" + 4.197 + header_line + "'"); 4.198 + System.err.println("ERROR: locked_line='" + line + "'"); 4.199 + error_cnt++; 4.200 + } 4.201 + } 4.202 + 4.203 + matcher = THREAD_STATE_RUNNABLE_PATTERN.matcher(thread_state_line); 4.204 + if (!matcher.matches()) { 4.205 + // It's strange, but a locked line can also 4.206 + // match the THREAD_STATE_BLOCKED_PATTERN. 4.207 + matcher = THREAD_STATE_BLOCKED_PATTERN.matcher( 4.208 + thread_state_line); 4.209 + if (!matcher.matches()) { 4.210 + System.err.println(); 4.211 + System.err.println("ERROR: thread state line does not " + 4.212 + "match runnable or waiting patterns."); 4.213 + System.err.println("ERROR: " + "thread_state_line='" + 4.214 + thread_state_line + "'"); 4.215 + System.err.println("ERROR: locked_line='" + line + "'"); 4.216 + error_cnt++; 4.217 + } 4.218 + } 4.219 + 4.220 + // Have everything we need from this thread stack 4.221 + // that matches the LOCK_PATTERN. 4.222 + have_header_line = false; 4.223 + have_thread_state_line = false; 4.224 + return true; 4.225 + } 4.226 + 4.227 + return false; 4.228 + } 4.229 + 4.230 + // Process the waiting line here if we found one. 4.231 + // 4.232 + // Example: 4.233 + // "ContendingThread-2" #22 prio=5 os_prio=64 tid=0x00000000007b9800 nid=0x30 waiting for monitor entry [0xfffffd7fc1010000] 4.234 + // java.lang.Thread.State: BLOCKED (on object monitor) 4.235 + // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:67) 4.236 + // - waiting to lock <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1) 4.237 + // at java.lang.Thread.run(Thread.java:745) 4.238 + // 4.239 + static boolean checkWaitingLine(String line) { 4.240 + Matcher matcher = WAITING_PATTERN.matcher(line); 4.241 + if (matcher.matches()) { 4.242 + if (verbose) { 4.243 + System.out.println("waiting_line='" + line + "'"); 4.244 + } 4.245 + 4.246 + matcher = HEADER_WAITING_PATTERN.matcher(header_line); 4.247 + if (!matcher.matches()) { 4.248 + System.err.println(); 4.249 + System.err.println("ERROR: header line does " + 4.250 + "not match a waiting pattern."); 4.251 + System.err.println("ERROR: header_line='" + header_line + "'"); 4.252 + System.err.println("ERROR: waiting_line='" + line + "'"); 4.253 + error_cnt++; 4.254 + } 4.255 + 4.256 + matcher = THREAD_STATE_BLOCKED_PATTERN.matcher(thread_state_line); 4.257 + if (!matcher.matches()) { 4.258 + System.err.println(); 4.259 + System.err.println("ERROR: thread state line " + 4.260 + "does not match a waiting pattern."); 4.261 + System.err.println("ERROR: thread_state_line='" + 4.262 + thread_state_line + "'"); 4.263 + System.err.println("ERROR: waiting_line='" + line + "'"); 4.264 + error_cnt++; 4.265 + } 4.266 + 4.267 + // Have everything we need from this thread stack 4.268 + // that matches the WAITING_PATTERN. 4.269 + have_header_line = false; 4.270 + have_thread_state_line = false; 4.271 + return true; 4.272 + } 4.273 + 4.274 + return false; 4.275 + } 4.276 + 4.277 + static void doSamples() throws Exception { 4.278 + for (int count = 0; count < n_samples; count++) { 4.279 + match_cnt = 0; 4.280 + // verbose mode or an error has a lot of output so add more space 4.281 + if (verbose || error_cnt > 0) System.out.println(); 4.282 + System.out.println("Sample #" + count); 4.283 + 4.284 + // We don't use the ProcessTools, OutputBuffer or 4.285 + // OutputAnalyzer classes from the testlibrary because 4.286 + // we have a complicated multi-line parse to perform 4.287 + // on a narrow subset of the JSTACK output. 4.288 + // 4.289 + // - we only care about stack traces that match 4.290 + // HEADER_PREFIX_PATTERN; only two should match 4.291 + // - we care about at most three lines from each stack trace 4.292 + // - if both stack traces match LOCKED_PATTERN, then that's 4.293 + // a failure and we report it 4.294 + // - for a stack trace that matches LOCKED_PATTERN, we verify: 4.295 + // - the header line matches HEADER_RUNNABLE_PATTERN 4.296 + // or HEADER_WAITING_PATTERN 4.297 + // - the thread state line matches THREAD_STATE_BLOCKED_PATTERN 4.298 + // or THREAD_STATE_RUNNABLE_PATTERN 4.299 + // - we report any mismatches as failures 4.300 + // - for a stack trace that matches WAITING_PATTERN, we verify: 4.301 + // - the header line matches HEADER_WAITING_PATTERN 4.302 + // - the thread state line matches THREAD_STATE_BLOCKED_PATTERN 4.303 + // - we report any mismatches as failures 4.304 + // - the stack traces that match HEADER_PREFIX_PATTERN may 4.305 + // not match either LOCKED_PATTERN or WAITING_PATTERN 4.306 + // because we might observe the thread outside of 4.307 + // monitor operations; this is not considered a failure 4.308 + // 4.309 + // When we do observe LOCKED_PATTERN or WAITING_PATTERN, 4.310 + // then we are checking the header and thread state patterns 4.311 + // that occurred earlier in the current stack trace that 4.312 + // matched HEADER_PREFIX_PATTERN. We don't use data from 4.313 + // stack traces that don't match HEADER_PREFIX_PATTERN and 4.314 + // we don't mix data between the two stack traces that do 4.315 + // match HEADER_PREFIX_PATTERN. 4.316 + // 4.317 + Process process = new ProcessBuilder(JSTACK, PID) 4.318 + .redirectErrorStream(true).start(); 4.319 + 4.320 + BufferedReader reader = new BufferedReader(new InputStreamReader( 4.321 + process.getInputStream())); 4.322 + String line; 4.323 + while ((line = reader.readLine()) != null) { 4.324 + Matcher matcher = null; 4.325 + 4.326 + // process the header line here 4.327 + if (!have_header_line) { 4.328 + matcher = HEADER_PREFIX_PATTERN.matcher(line); 4.329 + if (matcher.matches()) { 4.330 + if (verbose) { 4.331 + System.out.println(); 4.332 + System.out.println("header='" + line + "'"); 4.333 + } 4.334 + header_line = new String(line); 4.335 + have_header_line = true; 4.336 + continue; 4.337 + } 4.338 + continue; // skip until have a header line 4.339 + } 4.340 + 4.341 + // process the thread state line here 4.342 + if (!have_thread_state_line) { 4.343 + matcher = THREAD_STATE_PREFIX_PATTERN.matcher(line); 4.344 + if (matcher.matches()) { 4.345 + if (verbose) { 4.346 + System.out.println("thread_state='" + line + "'"); 4.347 + } 4.348 + thread_state_line = new String(line); 4.349 + have_thread_state_line = true; 4.350 + continue; 4.351 + } 4.352 + continue; // skip until we have a thread state line 4.353 + } 4.354 + 4.355 + // process the locked line here if we find one 4.356 + if (checkLockedLine(line)) { 4.357 + continue; 4.358 + } 4.359 + 4.360 + // process the waiting line here if we find one 4.361 + if (checkWaitingLine(line)) { 4.362 + continue; 4.363 + } 4.364 + 4.365 + // process the blank line here if we find one 4.366 + if (checkBlankLine(line)) { 4.367 + continue; 4.368 + } 4.369 + } 4.370 + process.waitFor(); 4.371 + 4.372 + if (match_cnt == 2) { 4.373 + if (match_list[0].equals(match_list[1])) { 4.374 + System.err.println(); 4.375 + System.err.println("ERROR: matching lock lines:"); 4.376 + System.err.println("ERROR: line[0]'" + match_list[0] + "'"); 4.377 + System.err.println("ERROR: line[1]'" + match_list[1] + "'"); 4.378 + error_cnt++; 4.379 + } 4.380 + } 4.381 + 4.382 + // slight delay between jstack launches 4.383 + Thread.sleep(500); 4.384 + } 4.385 + } 4.386 + 4.387 + // This helper relies on RuntimeMXBean.getName() returning a string 4.388 + // that looks like this: 5436@mt-haku 4.389 + // 4.390 + // The testlibrary has tryFindJvmPid(), but that uses a separate 4.391 + // process which is much more expensive for finding out your own PID. 4.392 + // 4.393 + static String getPid() { 4.394 + RuntimeMXBean runtimebean = ManagementFactory.getRuntimeMXBean(); 4.395 + String vmname = runtimebean.getName(); 4.396 + int i = vmname.indexOf('@'); 4.397 + if (i != -1) { 4.398 + vmname = vmname.substring(0, i); 4.399 + } 4.400 + return vmname; 4.401 + } 4.402 + 4.403 + static void usage() { 4.404 + System.err.println("Usage: " + 4.405 + "java TestThreadDumpMonitorContention [-v] [n_samples]"); 4.406 + System.exit(1); 4.407 + } 4.408 +}