1 /*
2 * Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 */
23
24 /*
25 * @test
26 * @bug 8036823
27 * @bug 8046287
28 * @summary Creates two threads contending for the same lock and checks
29 * whether jstack reports "locked" by more than one thread.
30 *
31 * @library /testlibrary
32 * @modules java.base/sun.misc
33 * java.management
34 * @run main/othervm TestThreadDumpMonitorContention
35 */
36
37 import java.io.BufferedReader;
38 import java.io.InputStreamReader;
39 import java.lang.management.ManagementFactory;
40 import java.lang.management.RuntimeMXBean;
41 import java.util.ArrayList;
42 import java.util.List;
43 import java.util.regex.Matcher;
44 import java.util.regex.Pattern;
45
46 import jdk.test.lib.*;
47
48 public class TestThreadDumpMonitorContention {
49 // jstack tends to be closely bound to the VM that we are running
50 // so use getTestJDKTool() instead of getCompileJDKTool() or even
51 // getJDKTool() which can fall back to "compile.jdk".
52 final static String JSTACK = JDKToolFinder.getTestJDKTool("jstack");
53 final static String PID = getPid();
54
55 // looking for header lines with these patterns:
56 // "ContendingThread-1" #19 prio=5 os_prio=64 tid=0x000000000079c000 nid=0x23 runnable [0xffff80ffb8b87000]
57 // "ContendingThread-2" #21 prio=5 os_prio=64 tid=0x0000000000780000 nid=0x2f waiting for monitor entry [0xfffffd7fc1111000]
58 // "ContendingThread-2" #24 prio=5 os_prio=64 tid=0x0000000000ec8800 nid=0x31 waiting on condition [0xfffffd7bbfffe000]
59 final static Pattern HEADER_PREFIX_PATTERN = Pattern.compile(
60 "^\"ContendingThread-.*");
61 final static Pattern HEADER_WAITING_PATTERN1 = Pattern.compile(
62 "^\"ContendingThread-.* waiting for monitor entry .*");
63 final static Pattern HEADER_WAITING_PATTERN2 = Pattern.compile(
64 "^\"ContendingThread-.* waiting on condition .*");
65 final static Pattern HEADER_RUNNABLE_PATTERN = Pattern.compile(
66 "^\"ContendingThread-.* runnable .*");
67
68 // looking for thread state lines with these patterns:
69 // java.lang.Thread.State: RUNNABLE
70 // java.lang.Thread.State: BLOCKED (on object monitor)
71 final static Pattern THREAD_STATE_PREFIX_PATTERN = Pattern.compile(
72 " *java\\.lang\\.Thread\\.State: .*");
73 final static Pattern THREAD_STATE_BLOCKED_PATTERN = Pattern.compile(
74 " *java\\.lang\\.Thread\\.State: BLOCKED \\(on object monitor\\)");
75 final static Pattern THREAD_STATE_RUNNABLE_PATTERN = Pattern.compile(
76 " *java\\.lang\\.Thread\\.State: RUNNABLE");
77
78 // looking for duplicates of this pattern:
79 // - locked <0x000000076ac59e20> (a TestThreadDumpMonitorContention$1)
80 final static Pattern LOCK_PATTERN = Pattern.compile(
81 ".* locked \\<.*\\(a TestThreadDumpMonitorContention.*");
82
83 // sanity checking header and thread state lines associated
84 // with this pattern:
85 // - waiting to lock <0x000000076ac59e20> (a TestThreadDumpMonitorContention$1)
86 final static Pattern WAITING_PATTERN = Pattern.compile(
87 ".* waiting to lock \\<.*\\(a TestThreadDumpMonitorContention.*");
88
89 final static Object barrier = new Object();
90 volatile static boolean done = false;
91
92 static int barrier_cnt = 0;
93 static int blank_line_match_cnt = 0;
94 static int error_cnt = 0;
95 static boolean have_header_line = false;
96 static boolean have_thread_state_line = false;
97 static String header_line = null;
98 static int header_prefix_match_cnt = 0;
99 static int locked_line_match_cnt = 0;
100 static String[] locked_match_list = new String[2];
101 static int n_samples = 15;
102 static int sum_both_running_cnt = 0;
103 static int sum_both_waiting_cnt = 0;
104 static int sum_contended_cnt = 0;
105 static int sum_locked_hdr_runnable_cnt = 0;
106 static int sum_locked_hdr_waiting1_cnt = 0;
107 static int sum_locked_hdr_waiting2_cnt = 0;
108 static int sum_locked_thr_state_blocked_cnt = 0;
109 static int sum_locked_thr_state_runnable_cnt = 0;
110 static int sum_one_waiting_cnt = 0;
111 static int sum_uncontended_cnt = 0;
112 static int sum_waiting_hdr_waiting1_cnt = 0;
113 static int sum_waiting_thr_state_blocked_cnt = 0;
114 static String thread_state_line = null;
115 static boolean verbose = false;
116 static int waiting_line_match_cnt = 0;
117
118 public static void main(String[] args) throws Exception {
119 if (args.length != 0) {
120 int arg_i = 0;
121 if (args[arg_i].equals("-v")) {
122 verbose = true;
123 arg_i++;
124 }
125
126 try {
127 n_samples = Integer.parseInt(args[arg_i]);
128 } catch (NumberFormatException nfe) {
129 System.err.println(nfe);
130 usage();
131 }
132 }
133
134 Runnable runnable = new Runnable() {
135 public void run() {
136 synchronized (barrier) {
137 // let the main thread know we're running
138 barrier_cnt++;
139 barrier.notify();
140 }
141 while (!done) {
142 synchronized (this) { }
143 }
144 }
145 };
146 Thread[] thread_list = new Thread[2];
147 thread_list[0] = new Thread(runnable, "ContendingThread-1");
148 thread_list[1] = new Thread(runnable, "ContendingThread-2");
149 synchronized (barrier) {
150 thread_list[0].start();
151 thread_list[1].start();
152
153 // Wait until the contending threads are running so that
154 // we don't sample any thread init states.
155 while (barrier_cnt < 2) {
156 barrier.wait();
157 }
158 }
159
160 doSamples();
161
162 done = true;
163
164 thread_list[0].join();
165 thread_list[1].join();
166
167 if (error_cnt == 0) {
168 System.out.println("Test PASSED.");
169 } else {
170 System.out.println("Test FAILED.");
171 throw new AssertionError("error_cnt=" + error_cnt);
172 }
173 }
174
175 // Reached a blank line which is the end of the
176 // stack trace without matching either LOCK_PATTERN
177 // or WAITING_PATTERN. Rare, but it's not an error.
178 //
179 // Example:
180 // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f runnable [0xfffffd7fc1111000]
181 // java.lang.Thread.State: RUNNABLE
182 // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140)
183 // at java.lang.Thread.run(Thread.java:745)
184 //
185 static boolean checkBlankLine(String line) {
186 if (line.length() == 0) {
187 blank_line_match_cnt++;
188 have_header_line = false;
189 have_thread_state_line = false;
190 return true;
191 }
192
193 return false;
194 }
195
196 // Process the locked line here if we found one.
197 //
198 // Example 1:
199 // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f runnable [0xfffffd7fc1111000]
200 // java.lang.Thread.State: RUNNABLE
201 // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140)
202 // - locked <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1)
203 // at java.lang.Thread.run(Thread.java:745)
204 //
205 // Example 2:
206 // "ContendingThread-1" #21 prio=5 os_prio=64 tid=0x00000000007b9000 nid=0x2f waiting for monitor entry [0xfffffd7fc1111000]
207 // java.lang.Thread.State: BLOCKED (on object monitor)
208 // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140)
209 // - locked <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1)
210 // at java.lang.Thread.run(Thread.java:745)
211 //
212 // Example 3:
213 // "ContendingThread-2" #24 prio=5 os_prio=64 tid=0x0000000000ec8800 nid=0x31 waiting on condition [0xfffffd7bbfffe000]
214 // java.lang.Thread.State: RUNNABLE
215 // JavaThread state: _thread_blocked
216 // Thread: 0x0000000000ec8800 [0x31] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
217 // JavaThread state: _thread_blocked
218 // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140)
219 // - locked <0xfffffd7e6d03eb28> (a TestThreadDumpMonitorContention$1)
220 // at java.lang.Thread.run(Thread.java:745)
221 //
222 static boolean checkLockedLine(String line) {
223 Matcher matcher = LOCK_PATTERN.matcher(line);
224 if (matcher.matches()) {
225 if (verbose) {
226 System.out.println("locked_line='" + line + "'");
227 }
228 locked_match_list[locked_line_match_cnt] = new String(line);
229 locked_line_match_cnt++;
230
231 matcher = HEADER_RUNNABLE_PATTERN.matcher(header_line);
232 if (matcher.matches()) {
233 sum_locked_hdr_runnable_cnt++;
234 } else {
235 // It's strange, but a locked line can also
236 // match the HEADER_WAITING_PATTERN{1,2}.
237 matcher = HEADER_WAITING_PATTERN1.matcher(header_line);
238 if (matcher.matches()) {
239 sum_locked_hdr_waiting1_cnt++;
240 } else {
241 matcher = HEADER_WAITING_PATTERN2.matcher(header_line);
242 if (matcher.matches()) {
243 sum_locked_hdr_waiting2_cnt++;
244 } else {
245 System.err.println();
246 System.err.println("ERROR: header line does " +
247 "not match runnable or waiting patterns.");
248 System.err.println("ERROR: header_line='" +
249 header_line + "'");
250 System.err.println("ERROR: locked_line='" + line +
251 "'");
252 error_cnt++;
253 }
254 }
255 }
256
257 matcher = THREAD_STATE_RUNNABLE_PATTERN.matcher(thread_state_line);
258 if (matcher.matches()) {
259 sum_locked_thr_state_runnable_cnt++;
260 } else {
261 // It's strange, but a locked line can also
262 // match the THREAD_STATE_BLOCKED_PATTERN.
263 matcher = THREAD_STATE_BLOCKED_PATTERN.matcher(
264 thread_state_line);
265 if (matcher.matches()) {
266 sum_locked_thr_state_blocked_cnt++;
267 } else {
268 System.err.println();
269 System.err.println("ERROR: thread state line does not " +
270 "match runnable or waiting patterns.");
271 System.err.println("ERROR: " + "thread_state_line='" +
272 thread_state_line + "'");
273 System.err.println("ERROR: locked_line='" + line + "'");
274 error_cnt++;
275 }
276 }
277
278 // Have everything we need from this thread stack
279 // that matches the LOCK_PATTERN.
280 have_header_line = false;
281 have_thread_state_line = false;
282 return true;
283 }
284
285 return false;
286 }
287
288 // Process the waiting line here if we found one.
289 //
290 // Example:
291 // "ContendingThread-2" #22 prio=5 os_prio=64 tid=0x00000000007b9800 nid=0x30 waiting for monitor entry [0xfffffd7fc1010000]
292 // java.lang.Thread.State: BLOCKED (on object monitor)
293 // at TestThreadDumpMonitorContention$1.run(TestThreadDumpMonitorContention.java:140)
294 // - waiting to lock <0xfffffd7e6a2912f8> (a TestThreadDumpMonitorContention$1)
295 // at java.lang.Thread.run(Thread.java:745)
296 //
297 static boolean checkWaitingLine(String line) {
298 Matcher matcher = WAITING_PATTERN.matcher(line);
299 if (matcher.matches()) {
300 waiting_line_match_cnt++;
301 if (verbose) {
302 System.out.println("waiting_line='" + line + "'");
303 }
304
305 matcher = HEADER_WAITING_PATTERN1.matcher(header_line);
306 if (matcher.matches()) {
307 sum_waiting_hdr_waiting1_cnt++;
308 } else {
309 System.err.println();
310 System.err.println("ERROR: header line does " +
311 "not match a waiting pattern.");
312 System.err.println("ERROR: header_line='" + header_line + "'");
313 System.err.println("ERROR: waiting_line='" + line + "'");
314 error_cnt++;
315 }
316
317 matcher = THREAD_STATE_BLOCKED_PATTERN.matcher(thread_state_line);
318 if (matcher.matches()) {
319 sum_waiting_thr_state_blocked_cnt++;
320 } else {
321 System.err.println();
322 System.err.println("ERROR: thread state line " +
323 "does not match a waiting pattern.");
324 System.err.println("ERROR: thread_state_line='" +
325 thread_state_line + "'");
326 System.err.println("ERROR: waiting_line='" + line + "'");
327 error_cnt++;
328 }
329
330 // Have everything we need from this thread stack
331 // that matches the WAITING_PATTERN.
332 have_header_line = false;
333 have_thread_state_line = false;
334 return true;
335 }
336
337 return false;
338 }
339
340 static void doSamples() throws Exception {
341 for (int count = 0; count < n_samples; count++) {
342 blank_line_match_cnt = 0;
343 header_prefix_match_cnt = 0;
344 locked_line_match_cnt = 0;
345 waiting_line_match_cnt = 0;
346 // verbose mode or an error has a lot of output so add more space
347 if (verbose || error_cnt > 0) System.out.println();
348 System.out.println("Sample #" + count);
349
350 // We don't use the ProcessTools, OutputBuffer or
351 // OutputAnalyzer classes from the testlibrary because
352 // we have a complicated multi-line parse to perform
353 // on a narrow subset of the JSTACK output.
354 //
355 // - we only care about stack traces that match
356 // HEADER_PREFIX_PATTERN; only two should match
357 // - we care about at most three lines from each stack trace
358 // - if both stack traces match LOCKED_PATTERN, then that's
359 // a failure and we report it
360 // - for a stack trace that matches LOCKED_PATTERN, we verify:
361 // - the header line matches HEADER_RUNNABLE_PATTERN
362 // or HEADER_WAITING_PATTERN{1,2}
363 // - the thread state line matches THREAD_STATE_BLOCKED_PATTERN
364 // or THREAD_STATE_RUNNABLE_PATTERN
365 // - we report any mismatches as failures
366 // - for a stack trace that matches WAITING_PATTERN, we verify:
367 // - the header line matches HEADER_WAITING_PATTERN1
368 // - the thread state line matches THREAD_STATE_BLOCKED_PATTERN
369 // - we report any mismatches as failures
370 // - the stack traces that match HEADER_PREFIX_PATTERN may
371 // not match either LOCKED_PATTERN or WAITING_PATTERN
372 // because we might observe the thread outside of
373 // monitor operations; this is not considered a failure
374 //
375 // When we do observe LOCKED_PATTERN or WAITING_PATTERN,
376 // then we are checking the header and thread state patterns
377 // that occurred earlier in the current stack trace that
378 // matched HEADER_PREFIX_PATTERN. We don't use data from
379 // stack traces that don't match HEADER_PREFIX_PATTERN and
380 // we don't mix data between the two stack traces that do
381 // match HEADER_PREFIX_PATTERN.
382 //
383 Process process = new ProcessBuilder(JSTACK, PID)
384 .redirectErrorStream(true).start();
385
386 BufferedReader reader = new BufferedReader(new InputStreamReader(
387 process.getInputStream()));
388 String line;
389 while ((line = reader.readLine()) != null) {
390 Matcher matcher = null;
391
392 // process the header line here
393 if (!have_header_line) {
394 matcher = HEADER_PREFIX_PATTERN.matcher(line);
395 if (matcher.matches()) {
396 header_prefix_match_cnt++;
397 if (verbose) {
398 System.out.println();
399 System.out.println("header='" + line + "'");
400 }
401 header_line = new String(line);
402 have_header_line = true;
403 continue;
404 }
405 continue; // skip until have a header line
406 }
407
408 // process the thread state line here
409 if (!have_thread_state_line) {
410 matcher = THREAD_STATE_PREFIX_PATTERN.matcher(line);
411 if (matcher.matches()) {
412 if (verbose) {
413 System.out.println("thread_state='" + line + "'");
414 }
415 thread_state_line = new String(line);
416 have_thread_state_line = true;
417 continue;
418 }
419 continue; // skip until we have a thread state line
420 }
421
422 // process the locked line here if we find one
423 if (checkLockedLine(line)) {
424 continue;
425 }
426
427 // process the waiting line here if we find one
428 if (checkWaitingLine(line)) {
429 continue;
430 }
431
432 // process the blank line here if we find one
433 if (checkBlankLine(line)) {
434 continue;
435 }
436 }
437 process.waitFor();
438
439 if (header_prefix_match_cnt != 2) {
440 System.err.println();
441 System.err.println("ERROR: should match exactly two headers.");
442 System.err.println("ERROR: header_prefix_match_cnt=" +
443 header_prefix_match_cnt);
444 error_cnt++;
445 }
446
447 if (locked_line_match_cnt == 2) {
448 if (locked_match_list[0].equals(locked_match_list[1])) {
449 System.err.println();
450 System.err.println("ERROR: matching lock lines:");
451 System.err.println("ERROR: line[0]'" +
452 locked_match_list[0] + "'");
453 System.err.println("ERROR: line[1]'" +
454 locked_match_list[1] + "'");
455 error_cnt++;
456 }
457 }
458
459 if (locked_line_match_cnt == 1) {
460 // one thread has the lock
461 if (waiting_line_match_cnt == 1) {
462 // and the other contended for it
463 sum_contended_cnt++;
464 } else {
465 // and the other is just running
466 sum_uncontended_cnt++;
467 }
468 } else if (waiting_line_match_cnt == 1) {
469 // one thread is waiting
470 sum_one_waiting_cnt++;
471 } else if (waiting_line_match_cnt == 2) {
472 // both threads are waiting
473 sum_both_waiting_cnt++;
474 } else {
475 // both threads are running
476 sum_both_running_cnt++;
477 }
478
479 // slight delay between jstack launches
480 Thread.sleep(500);
481 }
482
483 if (error_cnt != 0) {
484 // skip summary info since there were errors
485 return;
486 }
487
488 System.out.println("INFO: Summary for all samples:");
489 System.out.println("INFO: both_running_cnt=" + sum_both_running_cnt);
490 System.out.println("INFO: both_waiting_cnt=" + sum_both_waiting_cnt);
491 System.out.println("INFO: contended_cnt=" + sum_contended_cnt);
492 System.out.println("INFO: one_waiting_cnt=" + sum_one_waiting_cnt);
493 System.out.println("INFO: uncontended_cnt=" + sum_uncontended_cnt);
494 System.out.println("INFO: locked_hdr_runnable_cnt=" +
495 sum_locked_hdr_runnable_cnt);
496 System.out.println("INFO: locked_hdr_waiting1_cnt=" +
497 sum_locked_hdr_waiting1_cnt);
498 System.out.println("INFO: locked_hdr_waiting2_cnt=" +
499 sum_locked_hdr_waiting2_cnt);
500 System.out.println("INFO: locked_thr_state_blocked_cnt=" +
501 sum_locked_thr_state_blocked_cnt);
502 System.out.println("INFO: locked_thr_state_runnable_cnt=" +
503 sum_locked_thr_state_runnable_cnt);
504 System.out.println("INFO: waiting_hdr_waiting1_cnt=" +
505 sum_waiting_hdr_waiting1_cnt);
506 System.out.println("INFO: waiting_thr_state_blocked_cnt=" +
507 sum_waiting_thr_state_blocked_cnt);
508
509 if (sum_contended_cnt == 0) {
510 System.err.println("WARNING: the primary scenario for 8036823" +
511 " has not been exercised by this test run.");
512 }
513 }
514
515 // This helper relies on RuntimeMXBean.getName() returning a string
516 // that looks like this: 5436@mt-haku
517 //
518 // The testlibrary has tryFindJvmPid(), but that uses a separate
519 // process which is much more expensive for finding out your own PID.
520 //
521 static String getPid() {
522 RuntimeMXBean runtimebean = ManagementFactory.getRuntimeMXBean();
523 String vmname = runtimebean.getName();
524 int i = vmname.indexOf('@');
525 if (i != -1) {
526 vmname = vmname.substring(0, i);
527 }
528 return vmname;
529 }
530
531 static void usage() {
532 System.err.println("Usage: " +
533 "java TestThreadDumpMonitorContention [-v] [n_samples]");
534 System.exit(1);
535 }
536 }