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