JDK-8211392 : compiler/profiling/spectrapredefineclass_classloaders/Launcher.java times out in JDK12 CI
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11,12
  • Priority: P2
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2018-10-02
  • Updated: 2020-05-07
  • Resolved: 2018-10-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 11 JDK 12
11.0.8-oracleFixed 12 b14Fixed
Related Reports
Duplicate :  
JDK-8040237 - nsk/jvmti/RetransformClasses/retransform001 crashed the VM on all platforms when run with with -server -Xcomp
Relates :  
JDK-8132849 - Increased stop time in cleanup phase because of single-threaded walk of thread stacks in NMethodSweeper::mark_active_nmethods()
Description
The following test timed out in several JDK12 CI job sets:

compiler/profiling/spectrapredefineclass_classloaders/Launcher.java

Here's a snippet of on of the Linux log files:

----------System.out:(1/27)----------
Timeout refired 1200 times
----------System.err:(0/0)----------
----------rerun:(44/6326)*----------
cd /scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/scratch/3 && \\
HOME=/tmp/sparky-temp-home-1443722743808473608/user_home \\
JDK8_HOME=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk/10/46/bundles/linux-x64/jdk-10_linux-x64_bin.tar.gz/jdk-10 \\
JIB_DATA_DIR=/scratch/opt/mach5/mesos/work_dir/jib-master \\
JIB_HOME=/scratch/opt/mach5/mesos/work_dir/jib-master/install/com/oracle/java/jib/jib/3.0-SNAPSHOT/jib-3.0-SNAPSHOT-distribution.zip/jib-3.0-SNAPSHOT-distribution \\
JTREG_SHOWAGENT=true \\
JTREG_TIMEOUT_OPTION=-timeoutFactor:10 \\
JTREG_VERBOSE=fail,error,time \\
PATH=/bin:/usr/bin \\
TEST_IMAGE_GRAAL_DIR=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.test/hotspot/jtreg/graal \\
CLASSPATH=/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/compiler/profiling/spectrapredefineclass_classloaders/Launcher.d:/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/src.full/open/test/hotspot/jtreg/compiler/profiling/spectrapredefineclass_classloaders:/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/test/lib:/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/src.full/open/test/lib:/scratch/opt/mach5/mesos/work_dir/jib-master/install/java/re/jtreg/4.2/promoted/all/b13/bundles/jtreg_bin-4.2.zip/jtreg/lib/javatest.jar:/scratch/opt/mach5/mesos/work_dir/jib-master/install/java/re/jtreg/4.2/promoted/all/b13/bundles/jtreg_bin-4.2.zip/jtreg/lib/jtreg.jar \\
    /scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.jdk/jdk-12/fastdebug/bin/java \\
        -Dtest.class.path.prefix=/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/compiler/profiling/spectrapredefineclass_classloaders/Launcher.d:/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/src.full/open/test/hotspot/jtreg/compiler/profiling/spectrapredefineclass_classloaders:/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/test/lib \\
        -Dtest.src=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/src.full/open/test/hotspot/jtreg/compiler/profiling/spectrapredefineclass_classloaders \\
        -Dtest.src.path=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/src.full/open/test/hotspot/jtreg/compiler/profiling/spectrapredefineclass_classloaders:/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/src.full/open/test/lib \\
        -Dtest.classes=/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/compiler/profiling/spectrapredefineclass_classloaders/Launcher.d \\
        -Dtest.class.path=/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/compiler/profiling/spectrapredefineclass_classloaders/Launcher.d:/scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/classes/1/test/lib \\
        -Dtest.vm.opts=-XX:MaxRAMPercentage=6 \\
        -Dtest.tool.vm.opts=-J-XX:MaxRAMPercentage=6 \\
        -Dtest.compiler.opts= \\
        -Dtest.java.opts='-XX:+CreateCoredumpOnCrash -ea -esa -XX:CompileThreshold=100 -XX:+UnlockExperimentalVMOptions -server -XX:-TieredCompilation' \\
        -Dtest.jdk=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.jdk/jdk-12/fastdebug \\
        -Dcompile.jdk=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.jdk/jdk-12/fastdebug \\
        -Dtest.timeout.factor=10.0 \\
        -Dtest.modules='java.base/jdk.internal.misc java.instrument java.management' \\
        -Dtest.nativepath=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.test/hotspot/jtreg/native \\
        --add-modules java.base,java.instrument,java.management \\
        --add-exports java.base/jdk.internal.misc=ALL-UNNAMED \\
        -XX:MaxRAMPercentage=6 \\
        -XX:+CreateCoredumpOnCrash \\
        -ea \\
        -esa \\
        -XX:CompileThreshold=100 \\
        -XX:+UnlockExperimentalVMOptions \\
        -server \\
        -XX:-TieredCompilation \\
        -Djava.library.path=/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.test/hotspot/jtreg/native \\
        -XX:-TieredCompilation \\
        -XX:-BackgroundCompilation \\
        -XX:-UseOnStackReplacement \\
        -XX:TypeProfileLevel=222 \\
        -XX:ReservedCodeCacheSize=3M \\
        -Djdk.attach.allowAttachSelf \\
        com.sun.javatest.regtest.agent.MainWrapper /scratch/opt/mach5/mesos/work_dir/slaves/c4ee7e63-1ded-4e8c-9581-ce26f27e3af4-S267386/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3630ce69-5fb5-4d63-9c85-7e9554b7d6f9/runs/8e049b87-13db-4f09-ae8e-d31cfd3fdd22/testoutput/jtreg/JTwork/compiler/profiling/spectrapredefineclass_classloaders/Launcher.d/main.0.jta
result: Error. Program `/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.jdk/jdk-12/fastdebug/bin/java' timed out (timeout set to 1200000ms, elapsed time including timeout handling was 1373285ms).


test result: Error. Program `/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.550/linux-x64-debug.jdk/jdk-12/fastdebug/bin/java' timed out (timeout set to 1200000ms, elapsed time including timeout handling was 1373285ms).
Comments
jdk11 backport request I would like to have the patch in OpenJDK 11 as well (for better parity with 11.0.8_oracle). The patch applies cleanly.
05-05-2020
ILW = Test times out because many slow compilations are triggered (test bug, regression), single test in tier2/tier3, no workaround = MHH = P2
03-10-2018
Testing passed.
03-10-2018
http://cr.openjdk.java.net/~kvn/8211392/webrev.00/
02-10-2018
And also don't run these tests with -Xcomp.
02-10-2018
To clarify. With -XX:CompileThreshold=100 flag the test hit full CodeCache (it is small - 3Mb) and stop compilations before nmethod sweeper code changes. These changes help to continue compilation by more aggressively removing invalidated nmethods - this is good thing!!! But because we continue compilation with background compilation off, only C2, no OSR (-XX:-TieredCompilation -XX:-BackgroundCompilation -XX:-UseOnStackReplacement) execution of application is very slow and that is why it did not finish in 2 min. I suggest to add -XX:CompileThreshold=10000 to these tests @run command to overwrite passed value with default one.
02-10-2018
I narrowed test behavior change to nmethod sweeper code changes: JDK-8132849 + JDK-8211129.
02-10-2018
Seems like one of recent changes allows to remove invalid nmethods faster so that we don't hit full CodeCache and as result we continue compilation. C2 compiles a lot since testing passed -XX:CompileThreshold=100 flag which triggers a lot compilations (>8000).
02-10-2018
Test verified fix for JDK-8040237 related to class unloading and nmethods cleaning.
02-10-2018
Note the test uses very small CodeCache -XX:ReservedCodeCacheSize=3M and usually it switch off compilation: "CodeCache is full. Compiler has been disabled"
02-10-2018
If I read it correctly it seems we may be spending a lot time (cpu=1218801.17ms) in C2 and application waits compilation since it is -Xbatch mode: "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=1218801.17ms elapsed=1234.69s tid=0x00007f8adc44c000 nid=0x6853 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00007f8adc44c000 [0x6853] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked
02-10-2018
Rising priorities since it start failing recently and almost always.
02-10-2018