--- jsr166/src/test/tck/JSR166TestCase.java 2015/10/03 19:39:16 1.154 +++ jsr166/src/test/tck/JSR166TestCase.java 2015/10/09 16:24:12 1.173 @@ -7,6 +7,7 @@ */ import static java.util.concurrent.TimeUnit.MILLISECONDS; +import static java.util.concurrent.TimeUnit.MINUTES; import static java.util.concurrent.TimeUnit.NANOSECONDS; import java.io.ByteArrayInputStream; @@ -19,6 +20,8 @@ import java.lang.management.ThreadMXBean import java.lang.reflect.Constructor; import java.lang.reflect.Method; import java.lang.reflect.Modifier; +import java.nio.file.Files; +import java.nio.file.Paths; import java.security.CodeSource; import java.security.Permission; import java.security.PermissionCollection; @@ -51,6 +54,7 @@ import java.util.concurrent.ThreadFactor import java.util.concurrent.ThreadPoolExecutor; import java.util.concurrent.TimeoutException; import java.util.concurrent.atomic.AtomicReference; +import java.util.regex.Matcher; import java.util.regex.Pattern; import junit.framework.AssertionFailedError; @@ -187,7 +191,49 @@ public class JSR166TestCase extends Test return (regex == null) ? null : Pattern.compile(regex); } + // Instrumentation to debug very rare, but very annoying hung test runs. + static volatile TestCase currentTestCase; + // static volatile int currentRun = 0; + static { + Runnable checkForWedgedTest = new Runnable() { public void run() { + // avoid spurious reports with enormous runsPerTest + final int timeoutMinutes = Math.max(runsPerTest / 10, 1); + for (TestCase lastTestCase = currentTestCase;;) { + try { MINUTES.sleep(timeoutMinutes); } + catch (InterruptedException unexpected) { break; } + if (lastTestCase == currentTestCase) { + System.err.printf( + "Looks like we're stuck running test: %s%n", + lastTestCase); +// System.err.printf( +// "Looks like we're stuck running test: %s (%d/%d)%n", +// lastTestCase, currentRun, runsPerTest); + System.err.println("availableProcessors=" + + Runtime.getRuntime().availableProcessors()); + System.err.printf("cpu model = %s%n", cpuModel()); + dumpTestThreads(); + // one stack dump is probably enough; more would be spam + break; + } + lastTestCase = currentTestCase; + }}}; + Thread thread = new Thread(checkForWedgedTest, "checkForWedgedTest"); + thread.setDaemon(true); + thread.start(); + } + + public static String cpuModel() { + try { + Matcher matcher = Pattern.compile("model name\\s*: (.*)") + .matcher(new String( + Files.readAllBytes(Paths.get("/proc/cpuinfo")), "UTF-8")); + matcher.find(); + return matcher.group(1); + } catch (Exception ex) { return null; } + } + public void runBare() throws Throwable { + currentTestCase = this; if (methodFilter == null || methodFilter.matcher(toString()).find()) super.runBare(); @@ -195,6 +241,7 @@ public class JSR166TestCase extends Test protected void runTest() throws Throwable { for (int i = 0; i < runsPerTest; i++) { + // currentRun = i; if (profileTests) runTestProfiled(); else @@ -461,7 +508,6 @@ public class JSR166TestCase extends Test } else { return new TestSuite(); } - } // Delays for timing-dependent tests, in milliseconds. @@ -519,7 +565,8 @@ public class JSR166TestCase extends Test * the same test have no effect. */ public void threadRecordFailure(Throwable t) { - threadDump(); + System.err.println(t); + dumpTestThreads(); threadFailure.compareAndSet(null, t); } @@ -530,7 +577,7 @@ public class JSR166TestCase extends Test void tearDownFail(String format, Object... args) { String msg = toString() + ": " + String.format(format, args); System.err.println(msg); - threadDump(); + dumpTestThreads(); throw new AssertionFailedError(msg); } @@ -567,7 +614,7 @@ public class JSR166TestCase extends Test } /** - * Finds missing try { ... } finally { joinPool(e); } + * Finds missing PoolCleaners */ void checkForkJoinPoolThreadLeaks() throws InterruptedException { Thread[] survivors = new Thread[7]; @@ -726,47 +773,88 @@ public class JSR166TestCase extends Test /** * Delays, via Thread.sleep, for the given millisecond delay, but * if the sleep is shorter than specified, may re-sleep or yield - * until time elapses. + * until time elapses. Ensures that the given time, as measured + * by System.nanoTime(), has elapsed. */ static void delay(long millis) throws InterruptedException { - long startTime = System.nanoTime(); - long ns = millis * 1000 * 1000; - for (;;) { + long nanos = millis * (1000 * 1000); + final long wakeupTime = System.nanoTime() + nanos; + do { if (millis > 0L) Thread.sleep(millis); else // too short to sleep Thread.yield(); - long d = ns - (System.nanoTime() - startTime); - if (d > 0L) - millis = d / (1000 * 1000); - else - break; - } + nanos = wakeupTime - System.nanoTime(); + millis = nanos / (1000 * 1000); + } while (nanos >= 0L); } /** * Allows use of try-with-resources with per-test thread pools. */ - static class PoolCloser - implements AutoCloseable { - public final T pool; - public PoolCloser(T pool) { this.pool = pool; } + class PoolCleaner implements AutoCloseable { + private final ExecutorService pool; + public PoolCleaner(ExecutorService pool) { this.pool = pool; } public void close() { joinPool(pool); } } /** + * An extension of PoolCleaner that has an action to release the pool. + */ + class PoolCleanerWithReleaser extends PoolCleaner { + private final Runnable releaser; + public PoolCleanerWithReleaser(ExecutorService pool, Runnable releaser) { + super(pool); + this.releaser = releaser; + } + public void close() { + try { + releaser.run(); + } finally { + super.close(); + } + } + } + + PoolCleaner cleaner(ExecutorService pool) { + return new PoolCleaner(pool); + } + + PoolCleaner cleaner(ExecutorService pool, Runnable releaser) { + return new PoolCleanerWithReleaser(pool, releaser); + } + + PoolCleaner cleaner(ExecutorService pool, CountDownLatch latch) { + return new PoolCleanerWithReleaser(pool, releaser(latch)); + } + + Runnable releaser(final CountDownLatch latch) { + return new Runnable() { public void run() { + do { latch.countDown(); } + while (latch.getCount() > 0); + }}; + } + + /** * Waits out termination of a thread pool or fails doing so. */ - static void joinPool(ExecutorService pool) { + void joinPool(ExecutorService pool) { try { pool.shutdown(); - if (!pool.awaitTermination(2 * LONG_DELAY_MS, MILLISECONDS)) - fail("ExecutorService " + pool + - " did not terminate in a timely manner"); + if (!pool.awaitTermination(2 * LONG_DELAY_MS, MILLISECONDS)) { + try { + threadFail("ExecutorService " + pool + + " did not terminate in a timely manner"); + } finally { + // last resort, for the benefit of subsequent tests + pool.shutdownNow(); + pool.awaitTermination(MEDIUM_DELAY_MS, MILLISECONDS); + } + } } catch (SecurityException ok) { // Allowed in case test doesn't have privs } catch (InterruptedException fail) { - fail("Unexpected InterruptedException"); + threadFail("Unexpected InterruptedException"); } } @@ -779,9 +867,8 @@ public class JSR166TestCase extends Test * necessarily individually slow because they must block. */ void testInParallel(Action ... actions) { - try (PoolCloser poolCloser - = new PoolCloser<>(Executors.newCachedThreadPool())) { - ExecutorService pool = poolCloser.pool; + ExecutorService pool = Executors.newCachedThreadPool(); + try (PoolCleaner cleaner = cleaner(pool)) { ArrayList> futures = new ArrayList<>(actions.length); for (final Action action : actions) futures.add(pool.submit(new CheckedRunnable() { @@ -798,10 +885,10 @@ public class JSR166TestCase extends Test } /** - * A debugging tool to print all stack traces, as jstack does. + * A debugging tool to print stack traces of most threads, as jstack does. * Uninteresting threads are filtered out. */ - static void threadDump() { + static void dumpTestThreads() { ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); System.err.println("------ stacktrace dump start ------"); for (ThreadInfo info : threadMXBean.dumpAllThreads(true, true)) { @@ -814,6 +901,8 @@ public class JSR166TestCase extends Test if ("Finalizer".equals(name) && info.getLockName().startsWith("java.lang.ref.ReferenceQueue$Lock")) continue; + if ("checkForWedgedTest".equals(name)) + continue; System.err.print(info); } System.err.println("------ stacktrace dump end ------"); @@ -836,7 +925,7 @@ public class JSR166TestCase extends Test delay(millis); assertTrue(thread.isAlive()); } catch (InterruptedException fail) { - fail("Unexpected InterruptedException"); + threadFail("Unexpected InterruptedException"); } } @@ -858,7 +947,7 @@ public class JSR166TestCase extends Test for (Thread thread : threads) assertTrue(thread.isAlive()); } catch (InterruptedException fail) { - fail("Unexpected InterruptedException"); + threadFail("Unexpected InterruptedException"); } } @@ -1136,7 +1225,7 @@ public class JSR166TestCase extends Test } finally { if (t.getState() != Thread.State.TERMINATED) { t.interrupt(); - fail("Test timed out"); + threadFail("Test timed out"); } } } @@ -1284,11 +1373,22 @@ public class JSR166TestCase extends Test }}; } - public Runnable awaiter(final CountDownLatch latch) { - return new CheckedRunnable() { - public void realRun() throws InterruptedException { - await(latch); - }}; + class LatchAwaiter extends CheckedRunnable { + static final int NEW = 0; + static final int RUNNING = 1; + static final int DONE = 2; + final CountDownLatch latch; + int state = NEW; + LatchAwaiter(CountDownLatch latch) { this.latch = latch; } + public void realRun() throws InterruptedException { + state = 1; + await(latch); + state = 2; + } + } + + public LatchAwaiter awaiter(CountDownLatch latch) { + return new LatchAwaiter(latch); } public void await(CountDownLatch latch) {