AsyncSSLSocketClose.java has timing issue

AsyncSSLSocketClose.java times out when being executed with -Xcomp and -XX:-TieredCompilation because execution is slower and as a result the client thread hits the OutputStream buffer limit before the server thread calls Socket.close(). The client thread blocks forever in os.write(ba).

The same behavior can be triggered by this change:
diff -r 987508afad96 test/jdk/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.java
--- a/test/jdk/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.java Sun May 26 17:25:43 2019 -0700
+++ b/test/jdk/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.java Mon May 27 12:23:56 2019 +0200
@@ -92,6 +92,7 @@
 
         socket.setSoLinger(true, 10);
         System.out.println("Calling Socket.close");
+ Thread.sleep(1000);
         socket.close();
         System.out.println("ssl socket get closed");
         System.out.flush();
 
I wonder if that is even expected behavior according to the spec?


----------messages:(150/9065)----------
command: main AsyncSSLSocketClose
reason: User specified action: run main/othervm AsyncSSLSocketClose
Mode: othervm [/othervm specified]
Timeout information:
Running jstack on process 18825
2019-05-27 12:16:06
Full thread dump Java HotSpot(TM) 64-Bit Server VM (13-internal+0-adhoc.tobias.open compiled mode):

Threads class SMR info:
_java_thread_list=0x00007eff68002d50, length=11, elements={
0x00007effa4024000, 0x00007effa42e1000, 0x00007effa42e6800, 0x00007effa4319800,
0x00007effa431c000, 0x00007effa431e800, 0x00007effa43ad000, 0x00007effa452f000,
0x00007effa4580800, 0x00007eff50235000, 0x00007eff68001000
}
_java_thread_list_alloc_cnt=12, _java_thread_list_free_cnt=10, _java_thread_list_max=11, _nested_thread_list_max=1
_tlh_cnt=878, _tlh_times=1, avg_tlh_time=0.00, _tlh_time_max=1
_delete_lock_wait_cnt=0, _delete_lock_wait_max=0
_to_delete_list_cnt=0, _to_delete_list_max=1

"main" #1 prio=5 os_prio=0 cpu=1010.31ms elapsed=121.34s tid=0x00007effa4024000 nid=0x498c in Object.wait() [0x00007effac455000]
   java.lang.Thread.State: WAITING (on object monitor)
Thread: 0x00007effa4024000 [0x498c] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
at java.lang.Object.wait(java.base/Native Method)
- waiting on <no object reference available>
at java.lang.Thread.join(java.base/Thread.java:1303)
- locked <0x0000000717902bf8> (a java.lang.Thread)
at java.lang.Thread.join(java.base/Thread.java:1371)
at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.81ms elapsed=121.28s tid=0x00007effa42e1000 nid=0x4993 waiting on condition [0x00007eff943f0000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa42e1000 [0x4993] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
at java.lang.ref.Reference.waitForReferencePendingList(java.base/Native Method)
at java.lang.ref.Reference.processPendingReferences(java.base/Reference.java:241)
at java.lang.ref.Reference$ReferenceHandler.run(java.base/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.29ms elapsed=121.28s tid=0x00007effa42e6800 nid=0x4994 in Object.wait() [0x00007eff942ef000]
   java.lang.Thread.State: WAITING (on object monitor)
Thread: 0x00007effa42e6800 [0x4994] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
at java.lang.Object.wait(java.base/Native Method)
- waiting on <0x0000000717904168> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base/ReferenceQueue.java:155)
- locked <0x0000000717904168> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base/ReferenceQueue.java:176)
at java.lang.ref.Finalizer$FinalizerThread.run(java.base/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.38ms elapsed=121.27s tid=0x00007effa4319800 nid=0x4995 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa4319800 [0x4995] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=50156.91ms elapsed=121.27s tid=0x00007effa431c000 nid=0x4996 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa431c000 [0x4996] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"Sweeper thread" #7 daemon prio=9 os_prio=0 cpu=1017.75ms elapsed=121.27s tid=0x00007effa431e800 nid=0x4997 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa431e800 [0x4997] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Common-Cleaner" #8 daemon prio=8 os_prio=0 cpu=1.24ms elapsed=120.23s tid=0x00007effa43ad000 nid=0x4998 in Object.wait() [0x00007eff7ed7d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
Thread: 0x00007effa43ad000 [0x4998] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
at java.lang.Object.wait(java.base/Native Method)
- waiting on <no object reference available>
at java.lang.ref.ReferenceQueue.remove(java.base/ReferenceQueue.java:155)
- locked <0x0000000717906ee8> (a java.lang.ref.ReferenceQueue$Lock)
at jdk.internal.ref.CleanerImpl.run(java.base/CleanerImpl.java:148)
at java.lang.Thread.run(java.base/Thread.java:830)
at jdk.internal.misc.InnocuousThread.run(java.base/InnocuousThread.java:134)

"Service Thread" #9 daemon prio=9 os_prio=0 cpu=13.07ms elapsed=106.18s tid=0x00007effa452f000 nid=0x49a0 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa452f000 [0x49a0] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"MainThread" #11 prio=5 os_prio=0 cpu=3022.36ms elapsed=103.32s tid=0x00007effa4580800 nid=0x49a2 waiting on condition [0x00007eff7ea79000]
   java.lang.Thread.State: WAITING (parking)
Thread: 0x00007effa4580800 [0x49a2] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
at jdk.internal.misc.Unsafe.park(java.base/Native Method)
- parking to wait for <0x0000000709a2fb90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base/LockSupport.java:194)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base/AbstractQueuedSynchronizer.java:885)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base/AbstractQueuedSynchronizer.java:917)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base/AbstractQueuedSynchronizer.java:1240)
at java.util.concurrent.locks.ReentrantLock.lock(java.base/ReentrantLock.java:267)
at sun.security.ssl.SSLSocketImpl.duplexCloseOutput(java.base/SSLSocketImpl.java:621)
at sun.security.ssl.SSLSocketImpl.close(java.base/SSLSocketImpl.java:555)
at AsyncSSLSocketClose.<init>(AsyncSSLSocketClose.java:95)
at AsyncSSLSocketClose.main(AsyncSSLSocketClose.java:69)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base/NativeMethodAccessorImpl.java:62)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base/Method.java:567)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
at java.lang.Thread.run(java.base/Thread.java:830)

"Thread-1" #12 prio=5 os_prio=0 cpu=1587.97ms elapsed=81.27s tid=0x00007eff50235000 nid=0x49ae runnable [0x00007eff7df1d000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007eff50235000 [0x49ae] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_in_native
at java.net.SocketOutputStream.socketWrite0(java.base/Native Method)
at java.net.SocketOutputStream.socketWrite(java.base/SocketOutputStream.java:108)
at java.net.SocketOutputStream.write(java.base/SocketOutputStream.java:148)
at java.net.Socket$SocketOutputStream.write(java.base/Socket.java:980)
at sun.security.ssl.SSLSocketOutputRecord.deliver(java.base/SSLSocketOutputRecord.java:342)
at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(java.base/SSLSocketImpl.java:1181)
at java.io.OutputStream.write(java.base/OutputStream.java:122)
at AsyncSSLSocketClose.run(AsyncSSLSocketClose.java:124)
at java.lang.Thread.run(java.base/Thread.java:830)

"Attach Listener" #13 daemon prio=9 os_prio=0 cpu=0.47ms elapsed=0.10s tid=0x00007eff68001000 nid=0x49f5 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007eff68001000 [0x49f5] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"VM Thread" os_prio=0 cpu=35.21ms elapsed=121.29s tid=0x00007effa42c7000 nid=0x4992 runnable

"GC Thread#0" os_prio=0 cpu=19.58ms elapsed=121.33s tid=0x00007effa4092000 nid=0x498d runnable

"GC Thread#1" os_prio=0 cpu=9.44ms elapsed=65.80s tid=0x00007eff78001000 nid=0x49b2 runnable

"GC Thread#2" os_prio=0 cpu=8.76ms elapsed=65.80s tid=0x00007eff78002800 nid=0x49b3 runnable

"GC Thread#3" os_prio=0 cpu=9.41ms elapsed=65.80s tid=0x00007eff78004800 nid=0x49b4 runnable

"GC Thread#4" os_prio=0 cpu=8.59ms elapsed=65.80s tid=0x00007eff78006800 nid=0x49b5 runnable

"GC Thread#5" os_prio=0 cpu=12.28ms elapsed=65.80s tid=0x00007eff78008800 nid=0x49b6 runnable

"G1 Main Marker" os_prio=0 cpu=0.12ms elapsed=121.33s tid=0x00007effa40ab800 nid=0x498e runnable

"G1 Conc#0" os_prio=0 cpu=0.04ms elapsed=121.33s tid=0x00007effa40ad800 nid=0x498f runnable

"G1 Refine#0" os_prio=0 cpu=0.18ms elapsed=121.33s tid=0x00007effa41d3000 nid=0x4990 runnable

"G1 Young RemSet Sampling" os_prio=0 cpu=27.51ms elapsed=121.33s tid=0x00007effa41d5000 nid=0x4991 runnable
"VM Periodic Task Thread" os_prio=0 cpu=118.90ms elapsed=106.01s tid=0x00007effa4532800 nid=0x49a1 waiting on condition

JNI global refs: 16, weak refs: 0

--- Timeout information end.
elapsed time (seconds): 121.516
----------configuration:(0/0)----------
----------System.out:(9209/228061)----------
1024 bytes to be written
1024 bytes written
2048 bytes to be written
2048 bytes written
3072 bytes to be written
3072 bytes written
4096 bytes to be written
4096 bytes written
5120 bytes to be written
5120 bytes written
6144 bytes to be written
6144 bytes written
7168 bytes to be written
7168 bytes written
8192 bytes to be written
8192 bytes written
9216 bytes to be written
9216 bytes written
10240 bytes to be written
10240 bytes written
11264 bytes to be written
11264 bytes written
12288 bytes to be written
12288 bytes written
13312 bytes to be written
13312 bytes written

[...]

4714496 bytes to be written
Calling Socket.close
Timeout refired 120 times
----------System.err:(0/0)----------
----------rerun:(25/1532)*----------
cd /oracle/jdk_jdk/JTwork/scratch && \\
DISPLAY=:0 \\
GNOME_DESKTOP_SESSION_ID=this-is-deprecated \\
HOME=/home/tobias \\
LANG=en_US.UTF-8 \\
LD_LIBRARY_PATH=/oracle/documents/misc/ \\
PATH=/bin:/usr/bin \\
XMODIFIERS=@im=ibus \\
CLASSPATH=/oracle/jdk_jdk/JTwork/classes/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d:/oracle/jdk_jdk/open/test/jdk/sun/security/ssl/SSLSocketImpl:/home/tobias/programs/jtreg/lib/javatest.jar:/home/tobias/programs/jtreg/lib/jtreg.jar \\
    /oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/bin/java \\
        -Dtest.src=/oracle/jdk_jdk/open/test/jdk/sun/security/ssl/SSLSocketImpl \\
        -Dtest.src.path=/oracle/jdk_jdk/open/test/jdk/sun/security/ssl/SSLSocketImpl \\
        -Dtest.classes=/oracle/jdk_jdk/JTwork/classes/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d \\
        -Dtest.class.path=/oracle/jdk_jdk/JTwork/classes/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d \\
        -Dtest.vm.opts= \\
        -Dtest.tool.vm.opts= \\
        -Dtest.compiler.opts= \\
        -Dtest.java.opts='-XX:-TieredCompilation -Xcomp' \\
        -Dtest.jdk=/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk \\
        -Dcompile.jdk=/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk \\
        -Dtest.timeout.factor=1.0 \\
        -Dtest.root=/oracle/jdk_jdk/open/test/jdk \\
        -XX:-TieredCompilation \\
        -Xcomp \\
        com.sun.javatest.regtest.agent.MainWrapper /oracle/jdk_jdk/JTwork/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d/main.0.jta
result: Error. Program `/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/bin/java' timed out (timeout set to 120000ms, elapsed time including timeout handling was 121513ms).

test result: Error. Program `/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/bin/java' timed out (timeout set to 120000ms, elapsed time including timeout handling was 121513ms).