JDK-8150523 : improve jtreg test timeout handling, especially -timeout:
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.concurrent
  • Affected Version: 9
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2016-02-24
  • Updated: 2016-06-13
  • Resolved: 2016-03-03
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b109Fixed
Related Reports
Duplicate :  
JDK-8141596 - java/util/concurrent/ScheduledThreadPoolExecutor/GCRetention.java starts failing intermittently
Relates :  
JDK-8151501 - LockSupport/ParkLoops.java: AssertionError: lost unpark
Description
The test fails with the following error:

----------System.err:(13/652)----------
java.lang.AssertionError
	at DoneMeansDone.main(DoneMeansDone.java:96)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:520)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:92)
	at java.lang.Thread.run(Thread.java:804)

I'm able to reproduce this both with hs-comp and main:

jtreg -jdk:/oracle/hs/build/linux-x86_64-normal-server-fastdebug/jdk/ -verbose:all -vmoptions:"-server -Xcomp -XX:MaxRAMFraction=8 -XX:+CreateCoredumpOnCrash -ea -esa -XX:-TieredCompilation -XX:CompileThreshold=100 -XX:+UnlockExperimentalVMOptions" test/java/util/concurrent/FutureTask/DoneMeansDone.java
Comments
http://cr.openjdk.java.net/~martin/webrevs/openjdk9/jsr166-jdk9-integration/timeoutFactor/
27-02-2016
I'm widening the scope of this bug to cover all the jtreg tests
27-02-2016
I tried all the reporter's flags with fastdebug, and got "main:" run times of about 1 sec, so I can imagine occasional failures on slower machines. If the slowdown is due to C2 compilation, it's hard to have a meaningful timeout factor because so much of the run time is due to work that wouldn't get done at all if it were not for -Xcomp. But in practice a timeout factor of 100 is probably good enough (assuming that tests actually respect it!)
26-02-2016
I agree that timeouts used in j.u.concurrent tests should take the jtreg timeout factor into account. Historically jsr166 maintainers haven't done this, but it hasn't been a problem, probably because no one has tried to run these tests with adverserial VMs. I'm surprised that 10 sec is not enough. I did some ad hoc testing with a fastdebug jdk9, and this test always completed in less than 0.1 seconds. Perhaps it's the combination of fastdebug and other flags?
25-02-2016
Tests can run much more slowly than usual when certain JVM options are provided, so a timeout factor should be provided to jtreg in such cases. For example, JDK-8069242 shows a case where a timeout factor of 16 was used and it still wasn't long enough. (That case used fastdebug -Xcomp -XX:+DeoptimizeALot.) IN ADDITION, tests such as this one that have their own internal timeouts should multiply their timeout values by TIMEOUT_FACTOR as found in jdk/test/lib/testlibrary/jdk/testlibrary/Utils.java. This value is initialized from the test.timeout.factor property which is set by jtreg.
25-02-2016
That's very surprising. How big is the pool being shutdown? Can we observe lengthy compilations taking place? I think we need to be able to adjust timeout factors when Xcomp is used.
25-02-2016
[~dholmes], I first thought that as well but then reproduced the issue locally (without any load on my system). I'm able to reproduce this 1/10.
24-02-2016
That test run looks suspect to me. Check the "environment file and see how heavily the system was loaded at the time: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 23884 aurora 20 0 37.784g 361260 23120 S 629.4 0.1 0:09.17 javac 23981 aurora 20 0 37.780g 295768 18596 S 464.4 0.1 0:02.57 javac 23783 aurora 20 0 0 0 0 Z 200.0 0.0 0:11.43 javac 24088 aurora 20 0 37.773g 265904 13500 S 116.1 0.1 0:00.49 javac 11468 aurora 20 0 22.232g 246644 16664 S 103.9 0.1 0:20.00 java 23650 aurora 20 0 22.168g 203236 15716 S 103.9 0.1 0:03.59 java 12068 aurora 20 0 22.232g 240292 16320 S 97.8 0.1 0:14.36 java 23009 aurora 20 0 22.168g 213468 15932 S 97.8 0.1 0:07.84 java 23256 aurora 20 0 22.168g 211676 15872 S 97.8 0.1 0:06.14 java 23339 aurora 20 0 22.168g 211480 15876 S 97.8 0.1 0:06.00 java 23438 aurora 20 0 22.168g 205688 15844 S 97.8 0.1 0:05.03 java 23499 aurora 20 0 22.168g 205256 15844 S 97.8 0.1 0:04.90 java 23723 aurora 20 0 22.133g 202300 15548 S 97.8 0.1 0:02.84 java 23577 aurora 20 0 22.168g 204872 15808 S 91.7 0.1 0:04.54 java 11123 aurora 20 0 22.422g 249168 16588 S 79.4 0.1 0:23.22 java 24158 aurora 20 0 18340 1352 952 R 12.2 0.0 0:00.02 top
24-02-2016
Changing the timeout to 100s fixes the issue. For some reason, 10s is not enough (probably because of -Xcomp).
24-02-2016
This is the code that throws the Assert: if (!pool.awaitTermination(10L, TimeUnit.SECONDS)) throw new AssertionError();
24-02-2016