adoptium / adoptium/aqa-tests

jdk_net_0 randomly fail because BufferingSubscriberTest.java timeout on aarch64 platform

Open
#3,698 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
HTML
Stars
155
Forks
346
Avg merge
2d 9h
Merged PRs (30d)
36

Description

**Describe the bug**
jdk_net_0 randomly fail because BufferingSubscriberTest.java timeout on aarch64 platform

**To Reproduce**

Run the jtreg test test/jdk/java/net/httpclient/BufferingSubscriberTest.java parallel, and the timeout factor is set to 8, like make _jdk_net_0 do. The parallelism is set to the core number of process(128). But the total test count is 50, so the actual parallelism is 50.
```bash
test=test/jdk/java/net/httpclient/BufferingSubscriberTest.java
rm -rf tmp-jtreg ; mkdir -p tmp-jtreg ; seq 50 | xargs -i -n 1 -P `nproc` bash -c "jtreg -timeoutFactor:8 -v:fail,error,time,nopass -nr -w tmp-jtreg/index-{} $test &> tmp-jtreg/{}.log ; grep 'Test results: passed: 1' -L tmp-jtreg/{}.log"
```

![image](https://user-images.githubusercontent.com/24123821/169941484-aff01e4c-006d-4d74-8942-d89e599846c5.png)

Even throuht change parallelism from 8 to 32, there still randomly timeout for the same test.

**Expected behavior**
jdk_net_0 run pass on all platform everytime, thers is no randomly timeout.

**Screenshots**

**Additional context**
lscpu:

![image](https://user-images.githubusercontent.com/24123821/169938860-3ba21285-d41a-4ecc-a26f-36105a0f5364.png)

test log from aqa-tests:

[extended.openjdk.log](https://github.com/adoptium/aqa-tests/files/8759214/extended.openjdk.log)

```log
ACTION: testng -- Error. Program `/jvm/home/yansendao/software/jdk/2022-05/dragonwell-17.0.3.0.3+7-GA/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 960250ms).
REASON: User specified action: run testng/othervm -Djdk.internal.httpclient.debug=true BufferingSubscriberTest
TIME: 960.255 seconds
messages:
command: testng -Djdk.internal.httpclient.debug=true BufferingSubscriberTest
reason: User specified action: run testng/othervm -Djdk.internal.httpclient.debug=true BufferingSubscriberTest
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.net.http
Timeout information:
Running jstack on process 6763
2022-05-24 01:21:13
Full thread dump OpenJDK 64-Bit Server VM (17.0.3+7 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x0000ffff20001700, length=15, elements={
0x0000ffff78025030, 0x0000ffff78348f50, 0x0000ffff7834a3c0, 0x0000ffff7834f730,
0x0000ffff78350b70, 0x0000ffff78351fa0, 0x0000ffff783539c0, 0x0000ffff78354f50,
0x0000ffff783563e0, 0x0000ffff7836aa40, 0x0000ffff78397b10, 0x0000ffff783da9e0,
0x0000fffee80086c0, 0x0000fffef415fcc0, 0x0000ffff20000cd0
}

"main" #1 prio=5 os_prio=0 cpu=89.44ms elapsed=960.23s tid=0x0000ffff78025030 nid=0x1a71 in Object.wait() [0x0000ffff7f5d8000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@17.0.3/Native Method)
- waiting on <0x00000000fca00000> (a java.lang.Thread)
at java.lang.Thread.join(java.base@17.0.3/Thread.java:1304)
- locked <0x00000000fca00000> (a java.lang.Thread)
at java.lang.Thread.join(java.base@17.0.3/Thread.java:1372)
at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.52ms elapsed=960.21s tid=0x0000ffff78348f50 nid=0x1a86 waiting on condition [0x0000ffff493fe000]
java.lang.Thread.State: RUNNABLE
at java.lang.ref.Reference.waitForReferencePendingList(java.base@17.0.3/Native Method)
at java.lang.ref.Reference.processPendingReferences(java.base@17.0.3/Reference.java:253)
at java.lang.ref.Reference$ReferenceHandler.run(java.base@17.0.3/Reference.java:215)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.34ms elapsed=960.21s tid=0x0000ffff7834a3c0 nid=0x1a87 in Object.wait() [0x0000ffff491fe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@17.0.3/Native Method)
- waiting on <0x00000000fca1a488> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@17.0.3/ReferenceQueue.java:155)
- locked <0x00000000fca1a488> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@17.0.3/ReferenceQueue.java:176)
at java.lang.ref.Finalizer$FinalizerThread.run(java.base@17.0.3/Finalizer.java:172)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.31ms elapsed=960.21s tid=0x0000ffff7834f730 nid=0x1a89 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.68ms elapsed=960.21s tid=0x0000ffff78350b70 nid=0x1a8a runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=6.29ms elapsed=960.21s tid=0x0000ffff78351fa0 nid=0x1a8b runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=704.96ms elapsed=960.21s tid=0x0000ffff783539c0 nid=0x1a8c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task

"C1 CompilerThread0" #21 daemon prio=9 os_prio=0 cpu=216.86ms elapsed=960.21s tid=0x0000ffff78354f50 nid=0x1a8d waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task

"Sweeper thread" #28 daemon prio=9 os_prio=0 cpu=0.06ms elapsed=960.21s tid=0x0000ffff783563e0 nid=0x1a8e runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #29 daemon prio=8 os_prio=0 cpu=1.10ms elapsed=960.18s tid=0x0000ffff7836aa40 nid=0x1a92 in Object.wait() [0x0000ffff483fe000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@17.0.3/Native Method)
- waiting on <0x00000000fca05548> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@17.0.3/ReferenceQueue.java:155)
- locked <0x00000000fca05548> (a java.lang.ref.ReferenceQueue$Lock)
at jdk.internal.ref.CleanerImpl.run(java.base@17.0.3/CleanerImpl.java:140)
at java.lang.Thread.run(java.base@17.0.3/Thread.java:833)
at jdk.internal.misc.InnocuousThread.run(java.base@17.0.3/InnocuousThread.java:162)

"Notification Thread" #30 daemon prio=9 os_prio=0 cpu=0.07ms elapsed=960.16s tid=0x0000ffff78397b10 nid=0x1a9a runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"MainThread" #32 prio=5 os_prio=0 cpu=937.76ms elapsed=960.14s tid=0x0000ffff783da9e0 nid=0x1a9f waiting on condition [0x0000ffff26815000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.3/Native Method)
- parking to wait for <0x00000000f7fe0e48> (a java.util.concurrent.SubmissionPublisher$BufferedSubscription)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.3/LockSupport.java:211)
at java.util.concurrent.SubmissionPublisher$BufferedSubscription.block(java.base@17.0.3/SubmissionPublisher.java:1495)
at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.3/ForkJoinPool.java:3463)
at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.3/ForkJoinPool.java:3434)
at java.util.concurrent.SubmissionPublisher$BufferedSubscription.awaitSpace(java.base@17.0.3/SubmissionPublisher.java:1462)
at java.util.concurrent.SubmissionPublisher.retryOffer(java.base@17.0.3/SubmissionPublisher.java:455)
at java.util.concurrent.SubmissionPublisher.doOffer(java.base@17.0.3/SubmissionPublisher.java:432)
at java.util.concurrent.SubmissionPublisher.submit(java.base@17.0.3/SubmissionPublisher.java:520)
at BufferingSubscriberTest.source(BufferingSubscriberTest.java:383)
at BufferingSubscriberTest.test(BufferingSubscriberTest.java:181)
at BufferingSubscriberTest.test(BufferingSubscriberTest.java:140)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.3/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.3/NativeMethodAccessorImpl.java:77)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.3/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@17.0.3/Method.java:568)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
at org.testng.TestRunner$$Lambda$86/0x0000000800c2e6e0.accept(Unknown Source)
at java.util.ArrayList.forEach(java.base@17.0.3/ArrayList.java:1511)
at org.testng.TestRunner.privateRun(TestRunner.java:764)
at org.testng.TestRunner.run(TestRunner.java:585)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
at org.testng.SuiteRunner.run(SuiteRunner.java:286)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
at org.testng.TestNG.runSuites(TestNG.java:1069)
at org.testng.TestNG.run(TestNG.java:1037)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.3/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.3/NativeMethodAccessorImpl.java:77)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.3/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@17.0.3/Method.java:568)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
at java.lang.Thread.run(java.base@17.0.3/Thread.java:833)

"CompletableFutureDelayScheduler" #36 daemon prio=5 os_prio=0 cpu=36.72ms elapsed=959.80s tid=0x0000fffee80086c0 nid=0x1bd4 waiting on condition [0x0000ffff26416000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.3/Native Method)
- parking to wait for <0x00000000fca1f8f0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.3/LockSupport.java:341)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@17.0.3/AbstractQueuedSynchronizer.java:506)
at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.3/ForkJoinPool.java:3463)
at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.3/ForkJoinPool.java:3434)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@17.0.3/AbstractQueuedSynchronizer.java:1623)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.3/ScheduledThreadPoolExecutor.java:1170)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.3/ScheduledThreadPoolExecutor.java:899)
at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.3/ThreadPoolExecutor.java:1062)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.3/ThreadPoolExecutor.java:1122)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.3/ThreadPoolExecutor.java:635)
at java.lang.Thread.run(java.base@17.0.3/Thread.java:833)

"pool-18-thread-1" #56 prio=5 os_prio=0 cpu=156.54ms elapsed=955.71s tid=0x0000fffef415fcc0 nid=0x295e waiting on condition [0x0000ffff25c17000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.3/Native Method)
- parking to wait for <0x00000000fabeb660> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.3/LockSupport.java:341)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@17.0.3/AbstractQueuedSynchronizer.java:506)
at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.3/ForkJoinPool.java:3463)
at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.3/ForkJoinPool.java:3434)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@17.0.3/AbstractQueuedSynchronizer.java:1623)
at java.util.concurrent.LinkedBlockingQueue.take(java.base@17.0.3/LinkedBlockingQueue.java:435)
at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.3/ThreadPoolExecutor.java:1062)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.3/ThreadPoolExecutor.java:1122)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.3/ThreadPoolExecutor.java:635)
at java.lang.Thread.run(java.base@17.0.3/Thread.java:833)

"Attach Listener" #57 daemon prio=9 os_prio=0 cpu=0.18ms elapsed=0.10s tid=0x0000ffff20000cd0 nid=0x14ce8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=10.79ms elapsed=960.22s tid=0x0000ffff78344ee0 nid=0x1a85 runnable

"GC Thread#0" os_prio=0 cpu=3.74ms elapsed=960.23s tid=0x0000ffff7805be20 nid=0x1a78 runnable

"GC Thread#1" os_prio=0 cpu=2.96ms elapsed=956.51s tid=0x0000ffff40015100 nid=0x26e2 runnable

"GC Thread#2" os_prio=0 cpu=2.35ms elapsed=956.51s tid=0x0000ffff40015b40 nid=0x26e3 runnable

"GC Thread#3" os_prio=0 cpu=3.09ms elapsed=956.51s tid=0x0000ffff40016580 nid=0x26e4 runnable

"GC Thread#4" os_prio=0 cpu=2.99ms elapsed=956.51s tid=0x0000ffff40016fc0 nid=0x26e5 runnable

"GC Thread#5" os_prio=0 cpu=2.36ms elapsed=956.51s tid=0x0000ffff40017a00 nid=0x26e6 runnable

"GC Thread#6" os_prio=0 cpu=2.39ms elapsed=956.51s tid=0x0000ffff40018440 nid=0x26e7 runnable

"GC Thread#7" os_prio=0 cpu=2.31ms elapsed=956.51s tid=0x0000ffff40018e80 nid=0x26e8 runnable

"GC Thread#8" os_prio=0 cpu=2.96ms elapsed=956.51s tid=0x0000ffff40019cd0 nid=0x26e9 runnable

"GC Thread#9" os_prio=0 cpu=2.90ms elapsed=956.51s tid=0x0000ffff4001ab40 nid=0x26ea runnable

"GC Thread#10" os_prio=0 cpu=2.14ms elapsed=956.51s tid=0x0000ffff4001b9b0 nid=0x26eb runnable

"GC Thread#11" os_prio=0 cpu=2.97ms elapsed=956.51s tid=0x0000ffff4001c820 nid=0x26ec runnable

"G1 Main Marker" os_prio=0 cpu=0.05ms elapsed=960.23s tid=0x0000ffff78061510 nid=0x1a79 runnable

"G1 Conc#0" os_prio=0 cpu=0.06ms elapsed=960.23s tid=0x0000ffff78062510 nid=0x1a7a runnable

"G1 Refine#0" os_prio=0 cpu=0.06ms elapsed=960.22s tid=0x0000ffff78318e90 nid=0x1a82 runnable

"G1 Service" os_prio=0 cpu=155.86ms elapsed=960.22s tid=0x0000ffff78319d90 nid=0x1a83 runnable

"VM Periodic Task Thread" os_prio=0 cpu=84.56ms elapsed=960.16s tid=0x0000ffff783994f0 nid=0x1a9b waiting on condition

JNI global refs: 26, weak refs: 0

--- Timeout information end.
elapsed time (seconds): 960.255
configuration:
Boot Layer
add modules: java.net.http
```

timeout test log run from jtreg(dragonwell17):

![image](https://user-images.githubusercontent.com/24123821/169939697-d618a9e4-e626-4753-83cd-79135c2d0380.png)

[1.log](https://github.com/adoptium/aqa-tests/files/8759247/1.log)
[2.log](https://github.com/adoptium/aqa-tests/files/8759248/2.log)
[17.log](https://github.com/adoptium/aqa-tests/files/8759249/17.log)
[25.log](https://github.com/adoptium/aqa-tests/files/8759250/25.log)

temurin17:

![image](https://user-images.githubusercontent.com/24123821/169965881-7d527582-0f4d-4fcd-b824-660b649a5ce2.png)

[6.log](https://github.com/adoptium/aqa-tests/files/8760097/6.log)
[11.log](https://github.com/adoptium/aqa-tests/files/8760098/11.log)
[20.log](https://github.com/adoptium/aqa-tests/files/8760099/20.log)
[34.log](https://github.com/adoptium/aqa-tests/files/8760100/34.log)

Contributor guide

Open the contributing guide

Research direction

Start with test/jdk/java/net/httpclient/BufferingSubscriberTest.java, especially the test and source paths around lines 140, 181, and 383 shown in the thread. Reproduce it with the provided jtreg command on aarch64, varying parallelism and collecting the timeout logs and thread dump. Done means the test completes reliably without random timeouts under the reported parallel run.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
testing-qa
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.