Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8224829

AsyncSSLSocketClose.java has timing issue

    Details

    • Type: Bug
    • Status: Closed
    • Priority: P3
    • Resolution: Fixed
    • Affects Version/s: 13
    • Fix Version/s: 13
    • Component/s: security-libs
    • Labels:
    • Subcomponent:
    • Resolved In Build:
      b26
    • Verification:
      Verified

      Backports

        Description

        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).

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  xuelei Xue-Lei Fan
                  Reporter:
                  thartmann Tobias Hartmann
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  3 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: