--- jsr166/src/test/tck/JSR166TestCase.java 2015/09/14 03:14:01 1.144 +++ jsr166/src/test/tck/JSR166TestCase.java 2015/11/09 06:06:54 1.181 @@ -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; @@ -15,9 +16,12 @@ import java.io.ObjectInputStream; import java.io.ObjectOutputStream; import java.lang.management.ManagementFactory; import java.lang.management.ThreadInfo; +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; @@ -40,6 +44,7 @@ import java.util.concurrent.CyclicBarrie import java.util.concurrent.ExecutionException; import java.util.concurrent.Executors; import java.util.concurrent.ExecutorService; +import java.util.concurrent.ForkJoinPool; import java.util.concurrent.Future; import java.util.concurrent.RecursiveAction; import java.util.concurrent.RecursiveTask; @@ -49,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; @@ -106,8 +112,7 @@ import junit.framework.TestSuite; * methods as there are exceptions the method can throw. Sometimes * there are multiple tests per JSR166 method when the different * "normal" behaviors differ significantly. And sometimes testcases - * cover multiple methods when they cannot be tested in - * isolation. + * cover multiple methods when they cannot be tested in isolation. * *
  • The documentation style for testcases is to provide as javadoc * a simple sentence or two describing the property that the testcase @@ -170,6 +175,12 @@ public class JSR166TestCase extends Test private static final int suiteRuns = Integer.getInteger("jsr166.suiteRuns", 1); + /** + * The scaling factor to apply to standard delays used in tests. + */ + private static final int delayFactor = + Integer.getInteger("jsr166.delay.factor", 1); + public JSR166TestCase() { super(); } public JSR166TestCase(String name) { super(name); } @@ -185,27 +196,77 @@ public class JSR166TestCase extends Test return (regex == null) ? null : Pattern.compile(regex); } - protected void runTest() throws Throwable { + // 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. + // A single test case run should never take more than 1 second. + // But let's cap it at the high end too ... + final int timeoutMinutes = + Math.min(15, Math.max(runsPerTest / 60, 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()) { - for (int i = 0; i < runsPerTest; i++) { - if (profileTests) - runTestProfiled(); - else - super.runTest(); - } + || methodFilter.matcher(toString()).find()) + super.runBare(); + } + + protected void runTest() throws Throwable { + for (int i = 0; i < runsPerTest; i++) { + // currentRun = i; + if (profileTests) + runTestProfiled(); + else + super.runTest(); } } protected void runTestProfiled() throws Throwable { - // Warmup run, notably to trigger all needed classloading. - super.runTest(); - long t0 = System.nanoTime(); - try { + for (int i = 0; i < 2; i++) { + long startTime = System.nanoTime(); super.runTest(); - } finally { - long elapsedMillis = millisElapsedSince(t0); - if (elapsedMillis >= profileThreshold) + long elapsedMillis = millisElapsedSince(startTime); + if (elapsedMillis < profileThreshold) + break; + // Never report first run of any test; treat it as a + // warmup run, notably to trigger all needed classloading, + if (i > 0) System.out.printf("%n%s: %d%n", toString(), elapsedMillis); } } @@ -217,6 +278,34 @@ public class JSR166TestCase extends Test main(suite(), args); } + static class PithyResultPrinter extends junit.textui.ResultPrinter { + PithyResultPrinter(java.io.PrintStream writer) { super(writer); } + long runTime; + public void startTest(Test test) {} + protected void printHeader(long runTime) { + this.runTime = runTime; // defer printing for later + } + protected void printFooter(TestResult result) { + if (result.wasSuccessful()) { + getWriter().println("OK (" + result.runCount() + " tests)" + + " Time: " + elapsedTimeAsString(runTime)); + } else { + getWriter().println("Time: " + elapsedTimeAsString(runTime)); + super.printFooter(result); + } + } + } + + /** + * Returns a TestRunner that doesn't bother with unnecessary + * fluff, like printing a "." for each test case. + */ + static junit.textui.TestRunner newPithyTestRunner() { + junit.textui.TestRunner runner = new junit.textui.TestRunner(); + runner.setPrinter(new PithyResultPrinter(System.out)); + return runner; + } + /** * Runs all unit tests in the given test suite. * Actual behavior influenced by jsr166.* system properties. @@ -228,7 +317,7 @@ public class JSR166TestCase extends Test System.setSecurityManager(new SecurityManager()); } for (int i = 0; i < suiteRuns; i++) { - TestResult result = junit.textui.TestRunner.run(suite); + TestResult result = newPithyTestRunner().doRun(suite); if (!result.wasSuccessful()) System.exit(1); System.gc(); @@ -455,7 +544,6 @@ public class JSR166TestCase extends Test } else { return new TestSuite(); } - } // Delays for timing-dependent tests, in milliseconds. @@ -466,11 +554,11 @@ public class JSR166TestCase extends Test public static long LONG_DELAY_MS; /** - * Returns the shortest timed delay. This could - * be reimplemented to use for example a Property. + * Returns the shortest timed delay. This can be scaled up for + * slow machines using the jsr166.delay.factor system property. */ protected long getShortDelay() { - return 50; + return 50 * delayFactor; } /** @@ -513,6 +601,8 @@ public class JSR166TestCase extends Test * the same test have no effect. */ public void threadRecordFailure(Throwable t) { + System.err.println(t); + dumpTestThreads(); threadFailure.compareAndSet(null, t); } @@ -520,6 +610,13 @@ public class JSR166TestCase extends Test setDelays(); } + void tearDownFail(String format, Object... args) { + String msg = toString() + ": " + String.format(format, args); + System.err.println(msg); + dumpTestThreads(); + throw new AssertionFailedError(msg); + } + /** * Extra checks that get done for all test cases. * @@ -547,16 +644,16 @@ public class JSR166TestCase extends Test } if (Thread.interrupted()) - throw new AssertionFailedError("interrupt status set in main thread"); + tearDownFail("interrupt status set in main thread"); checkForkJoinPoolThreadLeaks(); } /** - * Finds missing try { ... } finally { joinPool(e); } + * Finds missing PoolCleaners */ void checkForkJoinPoolThreadLeaks() throws InterruptedException { - Thread[] survivors = new Thread[5]; + Thread[] survivors = new Thread[7]; int count = Thread.enumerate(survivors); for (int i = 0; i < count; i++) { Thread thread = survivors[i]; @@ -564,12 +661,15 @@ public class JSR166TestCase extends Test if (name.startsWith("ForkJoinPool-")) { // give thread some time to terminate thread.join(LONG_DELAY_MS); - if (!thread.isAlive()) continue; - throw new AssertionFailedError - (String.format("Found leaked ForkJoinPool thread test=%s thread=%s%n", - toString(), name)); + if (thread.isAlive()) + tearDownFail("Found leaked ForkJoinPool thread thread=%s", + thread); } } + + if (!ForkJoinPool.commonPool() + .awaitQuiescence(LONG_DELAY_MS, MILLISECONDS)) + tearDownFail("ForkJoin common pool thread stuck"); } /** @@ -582,7 +682,7 @@ public class JSR166TestCase extends Test fail(reason); } catch (AssertionFailedError t) { threadRecordFailure(t); - fail(reason); + throw t; } } @@ -709,37 +809,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. + */ + 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. */ 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"); } } @@ -753,7 +904,7 @@ public class JSR166TestCase extends Test */ void testInParallel(Action ... actions) { ExecutorService pool = Executors.newCachedThreadPool(); - try { + try (PoolCleaner cleaner = cleaner(pool)) { ArrayList> futures = new ArrayList<>(actions.length); for (final Action action : actions) futures.add(pool.submit(new CheckedRunnable() { @@ -766,19 +917,31 @@ public class JSR166TestCase extends Test } catch (Exception ex) { threadUnexpectedException(ex); } - } finally { - joinPool(pool); } } /** - * 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 printAllStackTraces() { - for (ThreadInfo info : - ManagementFactory.getThreadMXBean() - .dumpAllThreads(true, true)) + static void dumpTestThreads() { + ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); + System.err.println("------ stacktrace dump start ------"); + for (ThreadInfo info : threadMXBean.dumpAllThreads(true, true)) { + String name = info.getThreadName(); + if ("Signal Dispatcher".equals(name)) + continue; + if ("Reference Handler".equals(name) + && info.getLockName().startsWith("java.lang.ref.Reference$Lock")) + continue; + 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 ------"); } /** @@ -798,7 +961,7 @@ public class JSR166TestCase extends Test delay(millis); assertTrue(thread.isAlive()); } catch (InterruptedException fail) { - fail("Unexpected InterruptedException"); + threadFail("Unexpected InterruptedException"); } } @@ -820,7 +983,7 @@ public class JSR166TestCase extends Test for (Thread thread : threads) assertTrue(thread.isAlive()); } catch (InterruptedException fail) { - fail("Unexpected InterruptedException"); + threadFail("Unexpected InterruptedException"); } } @@ -1098,7 +1261,7 @@ public class JSR166TestCase extends Test } finally { if (t.getState() != Thread.State.TERMINATED) { t.interrupt(); - fail("Test timed out"); + threadFail("timed out waiting for thread to terminate"); } } } @@ -1239,16 +1402,36 @@ public class JSR166TestCase extends Test }}; } - public Runnable awaiter(final CountDownLatch latch) { + public Runnable countDowner(final CountDownLatch latch) { return new CheckedRunnable() { public void realRun() throws InterruptedException { - await(latch); + latch.countDown(); }}; } + 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) { try { - assertTrue(latch.await(LONG_DELAY_MS, MILLISECONDS)); + if (!latch.await(LONG_DELAY_MS, MILLISECONDS)) + fail("timed out waiting for CountDownLatch for " + + (LONG_DELAY_MS/1000) + " sec"); } catch (Throwable fail) { threadUnexpectedException(fail); } @@ -1256,7 +1439,9 @@ public class JSR166TestCase extends Test public void await(Semaphore semaphore) { try { - assertTrue(semaphore.tryAcquire(LONG_DELAY_MS, MILLISECONDS)); + if (!semaphore.tryAcquire(LONG_DELAY_MS, MILLISECONDS)) + fail("timed out waiting for Semaphore for " + + (LONG_DELAY_MS/1000) + " sec"); } catch (Throwable fail) { threadUnexpectedException(fail); }