JDK-8222448 : java/lang/reflect/PublicMethods/PublicMethodsTest.java times out
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.lang:reflect
  • Affected Version: 11,13
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: windows
  • CPU: x86_64
  • Submitted: 2019-04-15
  • Updated: 2021-06-30
  • Resolved: 2019-06-04
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 11 JDK 13 JDK 14
11.0.10-oracleFixed 13 b24Fixed 14Fixed
Related Reports
Relates :  
JDK-8226309 - [AOT] java/lang/reflect/PublicMethods/PublicMethodsTest.java timed out
Relates :  
JDK-8173112 - A lot of tests time out while executed with specific TieredStopAtLevel
Relates :  
JDK-8225349 - [AOT] java/lang/constant/MethodTypeDescTest.java timed out
Description
java/lang/reflect/PublicMethods/PublicMethodsTest.java fails with time out with Agent error: java.lang.Exception

See:
......
test result: Error. Agent error: java.lang.Exception: Agent 16 timed out with a timeout of 480 seconds; check console log for any additional details

See full log from comment
Comments
Fix Request (11u) This makes the test more reliable. Patch applies cleanly to 11u, affected test runs in fastdebug in 45 seconds before and in 30 seconds after. Patched JDK also passes tier1 and tier2 tests. Risk is low, as this is the testbug.
22-01-2020
I think it worths trying out the empty class path that Alan suggests as the experiment shows significant improvement in the test execution time. If the test fails again after this fix, we can look at other options.
04-06-2019
Who is on the hook for excluding the test?
03-06-2019
The patch to run the compilation tasks with an empty class path will eliminate the open/scan of the JAR files on the test class path and so helps significantly on Windows. The resulting test is compute bound but it generates a lot of work for the runtime compilers (huge portions of javac gets compiled as javac is invoked 1379 times to compile in-memory source files that are generated by the test). Here's what I see locally release real 0m11.785s user 0m35.750s sys 0m1.495s release -Xcomp real 0m34.712s user 0m35.105s sys 0m1.599s fastdebug real 0m51.651s user 2m25.217s sys 0m2.397s fastdebug -Xcomp real 2m36.880s user 3m7.910s sys 0m2.869s If fastdebug or fastdebug&-Xcomp runs are still too slow then we can exclude this test from being run - we have other tests with `@requires (vm.debug == false)` in their test description.
03-06-2019
Under local jtreg the test runs in 21s compared to only 12s direct. Locally for me fastdebug takes 4x longer than product! Fastdebug Xcomp timedout after 20 minutes and again after 30 minutes. So Xcomp induces >20x slowdown! Based on Alan's experiment with product bits in mach5 the test is slowest on Windows - fastest time seems to be 1m45s and ranges up to the 4m38 which is a bit of an outlier - but there are quite a few >3m executions on Windows. Alan indicates these tests are heavy on disk I/O and that Windows is known to be very slow on disk. Likely Windows VMs in mach5 are even slower than real Windows boxes.
02-06-2019
I had a brief discussion with Jon about the issue of the test not setting the class path. He suggested a few options. With the diff below, the run test in jtreg is the same as running the test standalone. On the slowest Windows machine that I could fine, this reduced the run time from ~40s to ~15s. Setting the class path to empty list avoids needing to open/scan the contents of jtreg.jar and its friends. ``` --- a/test/jdk/java/lang/reflect/PublicMethods/PublicMethodsTest.java Sat Jun 01 03:18:23 2019 +0200 +++ b/test/jdk/java/lang/reflect/PublicMethods/PublicMethodsTest.java Sun Jun 02 19:13:03 2019 +0100 @@ -222,6 +222,11 @@ StandardJavaFileManager standardJavaFileManager = javac.getStandardFileManager(errorsCollector, Locale.ROOT, Charset.forName("UTF-8")); + try { + standardJavaFileManager.setLocation(StandardLocation.CLASS_PATH, List.of()); + } catch (IOException e) { + throw new UncheckedIOException(e); + } TestFileManager testFileManager = new TestFileManager( standardJavaFileManager, source); ``` That said, I couldn't find any timeouts with product builds. All the logs that I looked at were fastdebug or AOT where it looks like the -timeoutFactor specified to jtreg isn't high enough.
02-06-2019
Accessing jtreg and other jar files via NFS has never been recommended. If possible, import jtreg to a temporary local directory before the test run. Also, jtreg no longer uses jh.jar, so make sure you're using a recent jtreg.
02-06-2019
Are there any observed timeouts with product builds and without exotic flags? I checked the logs from the timeouts that Kim reported and they all seem to be fastdebug builds. The other sightings seem to be AOT. This test is an exhaustive combo test. It generates a lot of test cases and invokes the compiler 1379 times. When run in jtreg, the class path will contain jtreg.jar and javatest.jar. In addition, jtreg has a Class-Path attribute that expands the class path to additionally include jh.jar and asmtools.jar. I think the compile tasks are inheriting the class path so each JAR files is opened as a zip file system by the compiler. So a lot going on, there are 5516 zip file systems created. In addition, there is a lot of code generated dynamically and the runtime compilers are kept busy. On macOS the test passes for me in ~11s standalone or ~17s when run by jtreg. On Windows it runs in ~28s standalone and ~45s in jtreg.
02-06-2019
Just a brief update on this. The really slow execution times that David sees when running the test with jtreg seem to be because jtreg is on a NFS file system in his environment. The test is a combo test and invokes the compiler (via the javax.tools API) more than 1000 times. Each compile sets up a class path and each JAR file (including jtreg) is opened as a zip file system. There doesn't seem to be any remote file systems in the picture when the timeouts are observed in the CI system so there may be sometime else going on.
31-05-2019
[~alanb] I don't see that on my linux box. Here's a product run: Running: jtreg -a -v:fail,error,time -retain:fail,error -ignore:quiet -exclude:ProblemList.txt -noreport -timeout:10 -J-Djavatest.maxOutputSize=10000000 -testjdk:../../../build/linux-x64/images/jdk -nativepath:/export/users/dh198349/jdk-dev/open/test/jdk/../../../build/linux-x64/images/test/jdk/jtreg/native java/lang/reflect/PublicMethods/PublicMethodsTest.java -------------------------------------------------- TEST: java/lang/reflect/PublicMethods/PublicMethodsTest.java build: 1.215 seconds compile: 1.211 seconds main: 418.424 seconds TEST RESULT: Passed. Execution successful -------------------------------------------------- Checking the CI for passed runs of this test the execution times extremely variable! The quickest is around 30s on Linux-x64 product, the slowest product run is 2m32s on sparc, but I also see 1m28s on Windows and 2m48 on macOS. They are all well under what I saw though - I'll rebuild and make sure I didn't have something unexpected turned on. Update: clean build showed the same - 420s. Even tried fixing a known bug just in case this hit that pathology but no difference. I'm mystified and will consult a performance expert.
28-05-2019
I tried a fastdebug build and the times aren't too bad (macOS 10.13.6, mid-2014 MBP, 2.2Ghz Core i7). #section:build elapsed time (seconds): 4.081 #section:compile elapsed time (seconds): 4.075 #section:main elapsed time (seconds): 100.478 The times in the CI seem to be very varied.
28-05-2019
I tried this test locally and it completes in ~24s with a product build. This is well within the default timeout of 120s. As always, fastdebug, -Xcomp, and AOT runs need jtreg to be run with a -timeoutFactor to give the tests enough time to pass. I looked at a few of the logs and they are timing out at 480s so I assume they are run with -timeoutFactor:4. Can this be increased? We could of course change the test description to specify /timeout but I assume there must be other tests with the same issue.
28-05-2019
Based on above comments, removing AOT label and changing 'Component' to core-libs. Please assign is back to hotspot/compiler if I missed something. Thanks.
28-05-2019
This looks to me like long running tests with inappropriate timeouts. I ran it locally on Linux without Xcomp or AOT: TEST: java/lang/reflect/PublicMethods/PublicMethodsTest.java build: 3.447 seconds compile: 3.441 seconds main: 478.893 seconds TEST RESULT: Passed. Execution successful -------------------------------------------------- That configuration has a 400 second timeout according to the logs. I would assign back to core-libs team so they can sanity check the test and set a specific timeout if needed.
27-05-2019
AOT belongs to the Compiler team. Moving from hotspot/runtime -> hotspot/compiler.
25-04-2019