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