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