[jboss-jira] [JBoss JIRA] (WFLY-9364) Closing an EJBClientContext sometimes hangs causing high CPU usage

Closing an EJBClientContext sometimes hangs causing high CPU usage ------------------------------------------------------------------ Key: WFLY-9364 URL: https://issues.jboss.org/browse/WFLY-9364 Project: WildFly Issue Type: Bug Affects Versions: 10.1.0.Final Environment: Server: - OS: Red Hat Enterprise Linux Server release 7.2 (Maipo) - JDK: java version "1.8.0_144" Java(TM) SE Runtime Environment (build 1.8.0_144-b01) Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode) - WildFly: WildFly 10.1.0.Final Client: - OS: Red Hat Enterprise Linux Server release 7.2 (Maipo) - JDK: java version "1.8.0_144" Java(TM) SE Runtime Environment (build 1.8.0_144-b01) Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode) Reporter: Marius Tantareanu Assignee: Jason Greene Attachments: echo-client.zip, output_rhel7.txt, output_win10.txt, simple-ear.ear, td_rhel7.txt, td_win10.txt 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).