Duplicate :
|
|
Relates :
|
|
Relates :
|
|
Relates :
|
|
Relates :
|
|
Relates :
|
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).
|