Bug ID: JDK-8273612 Fix for JDK-8272873 causes timeout in running some tests with -Xcomp

Versions (Unresolved/Resolved/Fixed)

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 18
18 b18Fixed

The timeout, which was mostly observed on the macosx-x64 platform, was first discovered in tier8 testing (see JDK-8273109).

When the test runtime/cds/appcds/loaderConstraints/DynamicLoaderConstraintsTest.java is run with the following vmoptions:
"-Xcomp -XX:+CreateCoredumpOnCrash -ea -esa -XX:CompileThreshold=100 -XX:+UnlockExperimentalVMOptions -server -XX:+TieredCompilation -XX:+DeoptimizeALot",
without the fix for JDK-8272873, the custom-cl case took around totalTime=744005. With the fix, the custom-cl timeout totalTime=1361245.

The slow down seems to be related to excessive inlining. Here's one example from the two attached log files:

Before:

  12578 2425    b  4       java.lang.invoke.InvokerBytecodeGenerator::emitPushArgument (150 bytes)
  12588 2424       3       java.lang.invoke.InvokerBytecodeGenerator::emitPushArgument (150 bytes)   made not entrant
  12588 2425   size: 3264(1088) time: 9 inlined: 60 bytes

After:
  54396 5810    b  4       java.lang.invoke.InvokerBytecodeGenerator::emitPushArgument (150 bytes)
  54796 5809       3       java.lang.invoke.InvokerBytecodeGenerator::emitPushArgument (150 bytes)   made not entrant
  54799 5810   size: 54872(23776) time: 402 inlined: 4651 bytes

Changeset: 83b22192 Author: Igor Veresov <iveresov@openjdk.org> Date: 2021-10-05 19:44:17 +0000 URL: https://git.openjdk.java.net/jdk/commit/83b2219220266c1365466970d08606fef766c4fa
05-10-2021
Total time spent in the compiler increased from 27 to 53 seconds ~/tmp$ grep 'time: ' custom-cl-before.log \| sed -e 's/.time: //g' -e 's/ .//g' \| paste -sd+ \| bc 27375 ~/tmp$ grep 'time: ' custom-cl-after.log \| sed -e 's/.time: //g' -e 's/ .//g' \| paste -sd+ \| bc 53531
29-09-2021
It seems like JDK-8272873 has made inlining more aggressive and slowed down the compilation of many methods. Before the change, there were 15 methods that took 100ms or more to compile. Afterwards, there were 101 methods $ grep 'time: ' custom-cl-before.log \| sed -e 's/.time: //g' \| sort -n \| grep '^... ' \| wc 15 60 356 $ grep 'time: ' custom-cl-after.log \| sed -e 's/.time: //g' \| sort -n \| grep '^... ' \| wc 101 404 2421 $ grep 'time: ' custom-cl-before.log \| sed -e 's/.time: //g' \| sort -n \| tail -20 84 inlined: 464 bytes 86 inlined: 1588 bytes 88 inlined: 116 bytes 93 inlined: 1442 bytes 98 inlined: 347 bytes 102 inlined: 126 bytes 102 inlined: 919 bytes 104 inlined: 126 bytes 115 inlined: 1793 bytes 133 inlined: 970 bytes 137 inlined: 3193 bytes 173 inlined: 1335 bytes 215 inlined: 2013 bytes 332 inlined: 2476 bytes 351 inlined: 2927 bytes 509 inlined: 3398 bytes 536 inlined: 3713 bytes 580 inlined: 3480 bytes 620 inlined: 4331 bytes 941 inlined: 3910 bytes $ grep 'time: ' custom-cl-after.log \| sed -e 's/.time: //g' \| sort -n \| tail -20 449 inlined: 2739 bytes 451 inlined: 7597 bytes 453 inlined: 4317 bytes 469 inlined: 8655 bytes 471 inlined: 8669 bytes 479 inlined: 3081 bytes 501 inlined: 3398 bytes 502 inlined: 7028 bytes 503 inlined: 7080 bytes 511 inlined: 7433 bytes 525 inlined: 7413 bytes 531 inlined: 3713 bytes 533 inlined: 7722 bytes 541 inlined: 4457 bytes 561 inlined: 7476 bytes 569 inlined: 7195 bytes 596 inlined: 7553 bytes 730 inlined: 7781 bytes 742 inlined: 6090 bytes 1014 inlined: 7299 bytes
17-09-2021
ILW = tests timeout = MMH = P3
10-09-2021
Attaching 2 logs with the output from -XX:+PrintCompilation -XX:+PrintCompilation2 from running the DynamicLoaderConstraintsTest.java test.
10-09-2021

Relates :	JDK-8272873 - C2: Inlining should not depend on absolute call site counts
Relates :	JDK-8273109 - runtime/cds/appcds/loaderConstraints/DynamicLoaderConstraintsTest times out
Relates :	JDK-8273509 - runtime/cds/appcds/loaderConstraints/DynamicLoaderConstraintsTest.java sub-tests fail with exitValue = 134
Relates :	JDK-8275328 - C2: assert(n->outcnt() != 0 \|\| C->top() == n \|\| n->is_Proj()) failed: No dead instructions after post-alloc
Relates :	JDK-8278420 - C2: assert(!n->is_Store() && !n->is_LoadStore()) failed: no node with a side effect
Relates :	JDK-8284944 - # assert(cnt++ < 40) failed: infinite cycle in loop optimization
Relates :	JDK-8273284 - runtime/cds/serviceability/ReplaceCriticalClasses.java timed out
Relates :	JDK-8275326 - C2: assert(no_dead_loop) failed: dead loop detected