JDK-8327978 : C2 SuperWord: Fix compilation time regression in dependency graph traversal after JDK-8325651
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 23
  • Priority: P4
  • Status: In Progress
  • Resolution: Unresolved
  • Submitted: 2024-03-12
  • Updated: 2024-03-28
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 23
23Unresolved
Related Reports
Relates :  
JDK-8323641 - Test compiler/loopopts/superword/TestAlignVectorFuzzer.java timed out
Relates :  
JDK-8325651 - C2 SuperWord: refactor the dependency graph
Description
Old title: TestAlignVectorFuzzer.java still times out

We are still seeing timeouts, even after JDK-8323641.


100719  404    b        compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH (1253 bytes)
Timeout signalled after 480 seconds
618487  407   !b        compiler.loopopts.superword.TestAlignVectorFuzzer::init_con (17 bytes)
618490  408   !b        compiler.loopopts.superword.TestAlignVectorFuzzer::init_is_con (17 bytes)
618494  409   !b        compiler.loopopts.superword.TestAlignVectorFuzzer::limit_con (17 bytes)
618497  410   !b        compiler.loopopts.superword.TestAlignVectorFuzzer::limit_is_con (17 bytes)
[629.271s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1552093071 to send result of operation jcmd
[629.271s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-239550605 to send result of operation jcmd
[629.272s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-313065970 to send result of operation jcmd
[629.273s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1475138679 to send result of operation jcmd
TEST PASSED: hit maximal time allownance during iteration 3, time allowance: -455947, until timeout: -147947
----------System.err:(1/16)----------
STATUS:Passed.

[...]

test result: Error. Program `c:\ade\mesos\work_dir\jib-master\install\jdk-23+14-1032\windows-x64-debug.jdk\jdk-23\fastdebug\bin\java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 639451ms).
Comments
I think I tracked down the slowdown. I think it is a regression of JDK-8325651. In JDK-8325651 I did a refactoring on the dependency graph, and missed a "!" in the maximum depth computation, meaning that we did not properly prune all the graph traversals for the independence checks. I extracted an example from TestAlignVectorFuzzer.java: /oracle-work/jdk-fork2/build/linux-x64/jdk/bin/java -XX:CompileCommand=printcompilation,TestGraph2::* -XX:CompileCommand=compileonly,TestGraph2::test* -XX:+CITime -XX:+UnlockDiagnosticVMOptions -XX:RepeatCompilation=0 -XX:LoopUnrollLimit=1000 -Xbatch TestGraph2.java With patch: C2 Compile Time: 8.234 s IdealLoop: 8.170 s AutoVectorize: 7.789 s master: C2 Compile Time: 56.223 s IdealLoop: 56.017 s AutoVectorize: 55.576 s
28-03-2024
I'll wait a little more on this, to see if there are more such failures, or if it was just some overloaded windows machines that were exceedingly slow.
13-03-2024
We have 3 failures so far, all on windows. ------------------------------- 1 -------------------------------------- To re-run test with same seed value please add "-Djdk.test.lib.random.seed=-3023988304919513453" to command line. init: 71360 (con: true) limit: 72857 (con: true) offset1: -284364 (con: true) offset2: -284364 (con: true) offset3: -284159 (con: false) stride: 1 scale: 4 hand_unrolling1: 12 hand_unrolling2: 1 hand_unrolling3: 16 ITERATION 3 of 5. Test testUUBBBH, time allowance: 72824, until timeout: 380824 100719 404 b compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH (1253 bytes) Timeout signalled after 480 seconds 618487 407 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_con (17 bytes) 618490 408 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_is_con (17 bytes) 618494 409 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_con (17 bytes) 618497 410 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_is_con (17 bytes) [629.271s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1552093071 to send result of operation jcmd [629.271s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-239550605 to send result of operation jcmd [629.272s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-313065970 to send result of operation jcmd [629.273s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1475138679 to send result of operation jcmd TEST PASSED: hit maximal time allownance during iteration 3, time allowance: -455947, until timeout: -147947 ------------------------------- 2 -------------------------------------- To re-run test with same seed value please add "-Djdk.test.lib.random.seed=-3023988304919513453" to command line. init: 71360 (con: true) limit: 72857 (con: true) offset1: -284364 (con: true) offset2: -284364 (con: true) offset3: -284159 (con: false) stride: 1 scale: 4 hand_unrolling1: 12 hand_unrolling2: 1 hand_unrolling3: 16 ITERATION 3 of 5. Test testUUBBBH, time allowance: 71550, until timeout: 379550 101917 404 b compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH (1253 bytes) Timeout signalled after 480 seconds 525831 407 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_con (17 bytes) 525834 408 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_is_con (17 bytes) 525837 409 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_con (17 bytes) 525839 410 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_is_con (17 bytes) [526.134s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool1116922108 to send result of operation jcmd TEST PASSED: hit maximal time allownance during iteration 3, time allowance: -352902, until timeout: -44902 ------------------------------- 3 -------------------------------------- CompileCommand: PrintCompilation compiler/loopopts/superword/TestAlignVectorFuzzer.* bool PrintCompilation = true For random generator using seed: 6196060673523836215 To re-run test with same seed value please add "-Djdk.test.lib.random.seed=6196060673523836215" to command line. 7536 173 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateB @ 8 (32 bytes) 7561 174 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateB (32 bytes) 7583 175 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateS @ 8 (32 bytes) 7609 176 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateS (32 bytes) 7675 177 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateC @ 8 (32 bytes) 7701 178 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateC (32 bytes) 7724 179 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateI @ 8 (31 bytes) 7749 180 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateI (31 bytes) 7777 182 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateL @ 8 (31 bytes) 7893 183 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateL (31 bytes) 8012 184 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateF @ 8 (34 bytes) 8037 185 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateF (34 bytes) 8062 186 % b compiler.loopopts.superword.TestAlignVectorFuzzer::generateD @ 8 (34 bytes) 8168 187 b compiler.loopopts.superword.TestAlignVectorFuzzer::generateD (34 bytes) Adjusted Timeout: 480000 Time Allowance: 172000 init: 623630 (con: false) limit: 624363 (con: false) offset1: -4988003 (con: true) offset2: -4988003 (con: true) offset3: -4987987 (con: true) stride: 1 scale: 8 hand_unrolling1: 4 hand_unrolling2: 8 hand_unrolling3: 15 ITERATION 1 of 5. Test testUUBBBH, time allowance: 171969, until timeout: 479969 8308 253 % b compiler.loopopts.superword.TestAlignVectorFuzzer::verifyB @ 3 (56 bytes) 8677 254 b compiler.loopopts.superword.TestAlignVectorFuzzer::verifyB (56 bytes) 8725 256 % b compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH @ 52 (1253 bytes) 8785 257 b compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH (1253 bytes) Timeout signalled after 480 seconds 557210 297 b compiler.loopopts.superword.TestAlignVectorFuzzer::verify (403 bytes) [557.238s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1041617456 to send result of operation jcmd [557.238s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1421200497 to send result of operation jcmd [557.239s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool494992994 to send result of operation jcmd 557443 305 b compiler.loopopts.superword.TestAlignVectorFuzzer::lambda$main$7 (25 bytes) 557450 306 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_con (17 bytes) 557452 307 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_is_con (17 bytes) 557454 308 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_con (17 bytes) 557457 309 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_is_con (17 bytes) 557459 310 !b compiler.loopopts.superword.TestAlignVectorFuzzer::offset1_con (17 bytes) 557462 311 !b compiler.loopopts.superword.TestAlignVectorFuzzer::offset1_is_con (17 bytes) 557464 312 !b compiler.loopopts.superword.TestAlignVectorFuzzer::offset2_con (17 bytes) 557467 313 !b compiler.loopopts.superword.TestAlignVectorFuzzer::offset2_is_con (17 bytes) 557469 314 !b compiler.loopopts.superword.TestAlignVectorFuzzer::offset3_con (17 bytes) 557472 315 !b compiler.loopopts.superword.TestAlignVectorFuzzer::offset3_is_con (17 bytes) TEST PASSED: hit maximal time allownance during iteration 1, time allowance: -377458, until timeout: -69458 ---------------------------------------------------- Case 1/2 have the same random seed, and fail in the same way. Case 3 fails with a different seed, but also with a large compilation time of the same test "testUUBBBH". All of them take 400-500 sec for a single compilation.
13-03-2024
A bit more from the logs: CompileCommand: PrintCompilation compiler/loopopts/superword/TestAlignVectorFuzzer.* bool PrintCompilation = true For random generator using seed: -3023988304919513453 To re-run test with same seed value please add "-Djdk.test.lib.random.seed=-3023988304919513453" to command line. ... init: 71360 (con: true) limit: 72857 (con: true) offset1: -284364 (con: true) offset2: -284364 (con: true) offset3: -284159 (con: false) stride: 1 scale: 4 hand_unrolling1: 12 hand_unrolling2: 1 hand_unrolling3: 16 ITERATION 3 of 5. Test testUUBBBH, time allowance: 72824, until timeout: 380824 100719 404 b compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH (1253 bytes) Timeout signalled after 480 seconds 618487 407 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_con (17 bytes) 618490 408 !b compiler.loopopts.superword.TestAlignVectorFuzzer::init_is_con (17 bytes) 618494 409 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_con (17 bytes) 618497 410 !b compiler.loopopts.superword.TestAlignVectorFuzzer::limit_is_con (17 bytes) [629.271s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1552093071 to send result of operation jcmd [629.271s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-239550605 to send result of operation jcmd [629.272s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-313065970 to send result of operation jcmd [629.273s][error][attach] could not open (2) pipe \\\\.\\pipe\\javatool-1475138679 to send result of operation jcmd TEST PASSED: hit maximal time allownance during iteration 3, time allowance: -455947, until timeout: -147947 ----------System.err:(1/16)---------- STATUS:Passed. Interesting are these two lines: ITERATION 3 of 5. Test testUUBBBH, time allowance: 72824, until timeout: 380824 TEST PASSED: hit maximal time allownance during iteration 3, time allowance: -455947, until timeout: -147947 We see that there was a time-gap of 528'771 milliseconds, which is mostly spent on compiling: compiler.loopopts.superword.TestAlignVectorFuzzer::testUUBBBH That is more than the budgeted 480 seconds for the whole test, i.e. the timeout. That is multiple minutes for a single compilation! In JDK-8323641, I got a report for a method that took 85 seconds, which would have easily passed here. Therefore, it looks like the fuzzing might generate these terrible outliers which take extremely long, while most tests are done very quickly. Maybe I can address the timeouts differently now: Rather than increasing the timeout, maybe we can do something to the SuperWord algorithm to lower computational complexity, and hence reduce the worst-case compile time?
12-03-2024
ILW = Same as JDK-8323641 = P4
12-03-2024