JDK11 Windows jdk_security java/security/SecureRandom/ApiTest.java & EnoughSeedTest.java timed out on some machines

[JasonFengJ9]

Failure link

From an internal build(win19x86-rt2-1):

openjdk version "11.0.18" 2023-01-17
IBM Semeru Runtime Open Edition 11.0.18.0 (build 11.0.18+10)
Eclipse OpenJ9 VM 11.0.18.0 (build openj9-0.36.0, JRE 11 Windows Server 2019 amd64-64-Bit Compressed References 20230207_562 (JIT enabled, AOT enabled)
OpenJ9   - e68fb241f
OMR      - f491bbf6f
JCL      - b732de1eee based on jdk-11.0.18+10)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2023-02-10T11:21:16.696Z] variation: Mode650
[2023-02-10T11:21:17.109Z] JVM_OPTIONS:  -XX:-UseCompressedOops 

[2023-02-10T11:53:11.669Z] TEST: java/security/SecureRandom/ApiTest.java

[2023-02-10T11:54:36.796Z] TEST: java/security/SecureRandom/EnoughSeedTest.java

[2023-02-10T11:54:36.804Z] TEST RESULT: Error. Program `C:\Users\jenkins\workspace\Test_openjdk11_j9_extended.openjdk_x86-64_windows_testList_2\openjdkbinary\j2sdk-image\bin\java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 984346ms).
[2023-02-10T11:54:36.804Z] --------------------------------------------------
[2023-02-10T12:00:20.415Z] Test results: passed: 200; error: 2
[2023-02-10T12:00:37.494Z] Report written to C:\Users\jenkins\workspace\Test_openjdk11_j9_extended.openjdk_x86-64_windows_testList_2\aqa-tests\TKG\output_16760205599427\jdk_security1_1\report\html\report.html
[2023-02-10T12:00:37.494Z] Results written to C:\Users\jenkins\workspace\Test_openjdk11_j9_extended.openjdk_x86-64_windows_testList_2\aqa-tests\TKG\output_16760205599427\jdk_security1_1\work
[2023-02-10T12:00:37.494Z] Error: Some tests failed or other problems occurred.
[2023-02-10T12:00:37.494Z] -----------------------------------
[2023-02-10T12:00:37.494Z] jdk_security1_1_FAILED

50x grinder - 11/50 failed

-Djdk.nativeCrypto=false doesn't help.

Adoptium JDK11 build has similar errors:

15:53:47  openjdk version "11.0.18" 2023-01-17
15:53:47  OpenJDK Runtime Environment Temurin-11.0.18+10 (build 11.0.18+10)
15:53:47  OpenJDK 64-Bit Server VM Temurin-11.0.18+10 (build 11.0.18+10, mixed mode)

https://openj9-jenkins.osuosl.org/job/Grinder_iteration_2/183 - win2019-x64-1
https://openj9-jenkins.osuosl.org/job/Grinder_iteration_3/153 - win2019-x64-2
https://openj9-jenkins.osuosl.org/job/Grinder_iteration_5/67 - win2012x64-openj9-1

From an internal investigation link

The specific test(s) timed out. There are two tests but they are both running the ThreadedSeedGenerator.

java/security/SecureRandom/ApiTest.java
java/security/SecureRandom/EnoughSeedTest.java

From the output you can see it's running the following code, the test is waiting on this.

15:04:17  "SeedGenerator Thread" prio=1 Id=27 RUNNABLE
15:04:17  	at [email protected]/sun.security.provider.SeedGenerator$ThreadedSeedGenerator.run(SeedGenerator.java:362)
15:04:17  	at [email protected]/java.lang.Thread.run(Thread.java:839)
Adoptium is the same

16:19:36  "SeedGenerator Thread" #15 daemon prio=1 os_prio=-2 cpu=958187.50ms elapsed=960.47s tid=0x0000020fb1e0a000 nid=0x195c runnable  [0x000000fde35fe000]
16:19:36     java.lang.Thread.State: RUNNABLE
16:19:36  	at sun.security.provider.SeedGenerator$ThreadedSeedGenerator.run([email protected]/SeedGenerator.java:362)
16:19:36  	at java.lang.Thread.run([email protected]/Thread.java:829)

In some of my grinders I collected diagnostics (javacore, core, etc.), and since my PR was merged this morning all of these runs will collect diagnostics. It's burning a lot of system CPU time (16+ min) running the ThreadedSeedGenerator loop. I suspected a JIT issue but the timeout also occurs with Adoptium. We could try increasing the timeout for the test, but I'm not sure it's worth it considering it already takes so long. For now we can just treat it as a known issue. It's possible the ThreadedSeedGenerator code is somewhat bogus, it looks to me like the loop counter < 64000 condition could result in running for a long time if the latch value, which loops around, ends up being quite small.

3XMTHREADINFO      "SeedGenerator Thread" J9VMThread:0x000000000025EA00, omrthread_t:0x0000023DC1DDB0B8, java/lang/Thread:0x00000000E0132C08, state:R, prio=1
3XMJAVALTHREAD            (java/lang/Thread getId:0x1B, isDaemon:true)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000000E0041570)
3XMTHREADINFO1            (native thread ID:0xEC, native priority:0x1, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 998.531250000 secs, user: 12.875000000 secs, system: 985.656250000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=94144 (0x16FC0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at sun/security/provider/SeedGenerator$ThreadedSeedGenerator.run(SeedGenerator.java:362(Compiled Code))
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:839)
The code waiting for the random bytes

4XESTACKTRACE                at java/lang/Object.wait(Native Method)
4XESTACKTRACE                at java/lang/Object.wait(Object.java:190(Compiled Code))
4XESTACKTRACE                at sun/security/provider/SeedGenerator$ThreadedSeedGenerator.getSeedByte(SeedGenerator.java:404(Compiled Code))
4XESTACKTRACE                at sun/security/provider/SeedGenerator$ThreadedSeedGenerator.getSeedBytes(SeedGenerator.java:393)
4XESTACKTRACE                at sun/security/provider/SeedGenerator.generateSeed(SeedGenerator.java:144)
4XESTACKTRACE                at sun/security/provider/AbstractDrbg.engineGenerateSeed(AbstractDrbg.java:456)
4XESTACKTRACE                at sun/security/provider/DRBG.engineGenerateSeed(DRBG.java:238)
4XESTACKTRACE                at java/security/SecureRandom.generateSeed(SecureRandom.java:874)
4XESTACKTRACE                at ApiTest.verifyAPI(ApiTest.java:258)

FYI @pshipton

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_windows_Nightly/560/ - win2019-x64-1a
java/security/SecureRandom/EnoughSeedTest.java
java/security/SecureRandom/ApiTest.java

[JasonFengJ9]

JDK11 x86-64_windows 0.40.0 rc1(win11x86-rt2-1)

23:45:30  variation: Mode650
23:45:31  JVM_OPTIONS:  -XX:-UseCompressedOops 

00:20:24  TEST: java/security/SecureRandom/ApiTest.java

00:22:49  TEST: java/security/SecureRandom/EnoughSeedTest.java

00:22:49  TEST RESULT: Error. Program `C:\Users\jenkins\workspace\Test_openjdk11_j9_sanity.openjdk_x86-64_windows_testList_5\openjdkbinary\j2sdk-image\bin\java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 1038546ms).
00:22:49  --------------------------------------------------
00:29:33  Test results: passed: 204; error: 2
00:30:01  Report written to C:\Users\jenkins\workspace\Test_openjdk11_j9_sanity.openjdk_x86-64_windows_testList_5\aqa-tests\TKG\output_16910343126346\jdk_security1_1\report\html\report.html
00:30:01  Results written to C:\Users\jenkins\workspace\Test_openjdk11_j9_sanity.openjdk_x86-64_windows_testList_5\aqa-tests\TKG\output_16910343126346\jdk_security1_1\work
00:30:01  Error: Some tests failed or other problems occurred.
00:30:01  -----------------------------------
00:30:01  jdk_security1_1_FAILED

[pshipton]

Created adoptium/aqa-tests#4707 to exclude the tests on Windows.