Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-9364

Closing an EJBClientContext sometimes hangs causing high CPU usage

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 11.0.0.Final
    • 10.1.0.Final
    • None
    • None
    • Hide

      I have used the out of the box WildFly 10.1.0 distribution with a single configuration change to add the "https" connector to the remoting subsystem:

      <http-connector name="https-remoting-connector" connector-ref="https" security-realm="ApplicationRealm"/>

      WildFly has been started with the following command (JAVA_HOME was defined in the environment):

      bin/standalone.sh -c standalone-full.xml

      • Deploy the attached EAR app into WildFly. The EAR contains a single EJB with a single method that just echoes back the String value it gets as parameter
      • Execute the attached client app. You can execute the "run.sh" script from the echo-client folder (JAVA_HOME environment variable must be set).
        The client connects to localhost:8443 using https-remoting protocol. It executes 1000 iterations as described above.
        If the client executes all 1000 iterations successfully, please run it again as the problem occurs randomly. Eventually it will get stuck.

      When it gets stuck the application output looks like the below (full output is attached). Iteration 401 completed successfully, iteration 402 got stuck
      (however the EJB client output does not indicate anything unusual).

      Starting iteration #401
      Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.VersionReceiver handleMessage
      INFO: EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
      Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver associate
      INFO: EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext

      {clientContext=org.jboss.ejb.client.EJBClientContext@645ba24a, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@5f6a8efe,channel=jboss.ejb,nodename=tv-395]}

      on channel Channel ID b71ebd7a (outbound) of Remoting connection 536da29c to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <58fbcb71>
      Result from EchoService: hello
      Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.ChannelAssociation$ResponseReceiver handleEnd
      INFO: EJBCLIENT000016: Channel Channel ID b71ebd7a (outbound) of Remoting connection 536da29c to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <58fbcb71> can no longer process messages
      Starting iteration #402
      Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.VersionReceiver handleMessage
      INFO: EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
      Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver associate
      INFO: EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext

      {clientContext=org.jboss.ejb.client.EJBClientContext@370a8b6e, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@118fbaf0,channel=jboss.ejb,nodename=tv-395]}

      on channel Channel ID e8f61ae2 (outbound) of Remoting connection 693f2c89 to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <50b4364>
      Result from EchoService: hello
      Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.ChannelAssociation$ResponseReceiver handleEnd
      INFO: EJBCLIENT000016: Channel Channel ID e8f61ae2 (outbound) of Remoting connection 693f2c89 to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <50b4364> can no longer process messages

      Show
      I have used the out of the box WildFly 10.1.0 distribution with a single configuration change to add the "https" connector to the remoting subsystem: <http-connector name="https-remoting-connector" connector-ref="https" security-realm="ApplicationRealm"/> WildFly has been started with the following command (JAVA_HOME was defined in the environment): bin/standalone.sh -c standalone-full.xml Deploy the attached EAR app into WildFly. The EAR contains a single EJB with a single method that just echoes back the String value it gets as parameter Execute the attached client app. You can execute the "run.sh" script from the echo-client folder (JAVA_HOME environment variable must be set). The client connects to localhost:8443 using https-remoting protocol. It executes 1000 iterations as described above. If the client executes all 1000 iterations successfully, please run it again as the problem occurs randomly. Eventually it will get stuck. When it gets stuck the application output looks like the below (full output is attached). Iteration 401 completed successfully, iteration 402 got stuck (however the EJB client output does not indicate anything unusual). Starting iteration #401 Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.VersionReceiver handleMessage INFO: EJBCLIENT000017: Received server version 2 and marshalling strategies [river] Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver associate INFO: EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext {clientContext=org.jboss.ejb.client.EJBClientContext@645ba24a, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@5f6a8efe,channel=jboss.ejb,nodename=tv-395]} on channel Channel ID b71ebd7a (outbound) of Remoting connection 536da29c to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <58fbcb71> Result from EchoService: hello Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.ChannelAssociation$ResponseReceiver handleEnd INFO: EJBCLIENT000016: Channel Channel ID b71ebd7a (outbound) of Remoting connection 536da29c to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <58fbcb71> can no longer process messages Starting iteration #402 Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.VersionReceiver handleMessage INFO: EJBCLIENT000017: Received server version 2 and marshalling strategies [river] Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver associate INFO: EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext {clientContext=org.jboss.ejb.client.EJBClientContext@370a8b6e, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@118fbaf0,channel=jboss.ejb,nodename=tv-395]} on channel Channel ID e8f61ae2 (outbound) of Remoting connection 693f2c89 to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <50b4364> Result from EchoService: hello Sep 19, 2017 11:07:29 AM org.jboss.ejb.client.remoting.ChannelAssociation$ResponseReceiver handleEnd INFO: EJBCLIENT000016: Channel Channel ID e8f61ae2 (outbound) of Remoting connection 693f2c89 to localhost/127.0.0.1:8443 of endpoint "config-based-ejb-client-endpoint" <50b4364> can no longer process messages

    Description

      EJBClientContext.close() sometimes hangs and causes high CPU usage. We have a WildFly client that uses EJB client API to invoke some EJBs remotely.
      Basically the client executes the following actions in a loop:

      • setup an EJBClientContext programatically
      • create a JNDI context
      • lookup an EJB and invoke some operations on it
      • close the JNDI context and the EJBClientContext

      After the client runs a few hundreds iterations (the actual number of iterations varies quite a lot from one run to another) it blocks while invoking EJBClientContext.close(). Also one XNIO thread in the client app is constantly consuming one CPU core (full thread dump from the client app is attached). I was only able to reproduce this when connecting over TLS (port 8443). When using the unsecure port (8080) the problem does not reproduce (or it reproduces much less frequently and I didn't run enough iterations to catch it).
      Once the client app enters this state, top shows something like (notice the CPU usage of thread 12512):

      >top -H -p 6463

      PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
      12512 root 20 0 11.527g 222680 13788 R 99.3 0.7 141:10.99 java
      6466 root 20 0 11.527g 222680 13788 S 0.3 0.7 0:07.05 java
      6467 root 20 0 11.527g 222680 13788 S 0.3 0.7 0:06.97 java
      6477 root 20 0 11.527g 222680 13788 S 0.3 0.7 0:04.24 java
      6463 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      6464 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:03.46 java
      6465 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:06.94 java
      6468 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:07.02 java
      6469 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:16.42 java
      6470 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.01 java
      6471 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.01 java
      6472 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      6473 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:06.87 java
      6474 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:06.70 java
      6475 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:03.09 java
      6476 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12513 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12514 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12515 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12516 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12517 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12518 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12519 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12520 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12523 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12524 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java
      12597 root 20 0 11.527g 222680 13788 S 0.0 0.7 0:00.00 java

      The thread that causes the CPU usage is the following:

      "Remoting "config-based-ejb-client-endpoint" I/O-1" #6025 daemon prio=5 os_prio=0 tid=0x00007f2f709d3000 nid=0x30e0 runnable [0x00007f2e7f9be000]
      java.lang.Thread.State: RUNNABLE
      at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
      at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
      at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
      at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

      • locked <0x00000005cc1844e8> (a sun.nio.ch.Util$3)
      • locked <0x00000005cc19f258> (a java.util.Collections$UnmodifiableSet)
      • locked <0x00000005cc184468> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:515)

      The client app main thread is blocked as below:

      "main" #1 prio=5 os_prio=0 tid=0x00007f2f70008800 nid=0x1940 in Object.wait() [0x00007f2f76350000]
      java.lang.Thread.State: WAITING (on object monitor)
      at java.lang.Object.wait(Native Method)
      at java.lang.Object.wait(Object.java:502)
      at org.jboss.remoting3.spi.AbstractHandleableCloseable.close(AbstractHandleableCloseable.java:190)

      • locked <0x00000005cc18de48> (a java.lang.Object)
        at org.jboss.ejb.client.remoting.ConnectionPool.safeClose(ConnectionPool.java:177)
        at org.jboss.ejb.client.remoting.ConnectionPool.release(ConnectionPool.java:104)
      • locked <0x00000005cbd369e0> (a org.jboss.ejb.client.remoting.ConnectionPool)
        at org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection.close(ConnectionPool.java:198)
        at org.jboss.ejb.client.remoting.RemotingConnectionManager.safeClose(RemotingConnectionManager.java:65)
      • locked <0x00000005cc1a6840> (a java.util.Collections$SynchronizedRandomAccessList)
        at org.jboss.ejb.client.remoting.ConfigBasedEJBClientContextSelector$ContextCloseListener.contextClosed(ConfigBasedEJBClientContextSelector.java:220)
        at org.jboss.ejb.client.EJBClientContext.close(EJBClientContext.java:1305)
      • locked <0x00000005cc1a6888> (a org.jboss.ejb.client.EJBClientContext)
        at com.microfocus.echoclient.EchoClient.disconnect(EchoClient.java:66)
        at com.microfocus.echoclient.EchoClient.connectDisconnect(EchoClient.java:54)
        at com.microfocus.echoclient.EchoClient.main(EchoClient.java:36)

      The problem also reproduces on Windows (full thread dump of the client app is attached).

      Attachments

        1. echo-client.zip
          9.72 MB
        2. output_rhel7.txt
          438 kB
        3. output_win10.txt
          474 kB
        4. simple-ear.ear
          2 kB
        5. td_rhel7.txt
          15 kB
        6. td_win10.txt
          15 kB

        Activity

          People

            jgreene@redhat.com Jason Greene
            mariustant Marius Tantareanu (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: