Performance degradation on standalone EJB remote invocation on a Windows client when using PROVIDER_URL on EAP 7.2

Solution Verified - Updated

Environment

  • Red Hat JBoss Enterprise Application Platform (EAP)
    • 7.2
  • Enterprise Java Beans (EJB)
  • Remoting/HTTP Remoting from Windows client

Issue

  • Performance degradation on Windows standalone client when using PROVIDER_URL and one of the included nodes is down

Resolution

A fix for this issue will be available with an upcoming cumulative patch (currently targeting JBoss EAP 7.2 CP8). The issue will be fixed with This content is not included.JBEAP-18565.

For now the workaround (if using the programmatic approach with an InitialContextand PROVIDER_URLis required), is to start the node that is contained in the list of the the PROVIDER_URL list again, or if it is permanently down, remove it from the client's PROVIDER_URL.

Note:
This issue does not exist when using a declarative approach using wildfly-config.xml.

Root Cause

On a Windows machine the native call get stuck for 1 second if the selected destination node is an absent node from the PROVIDER_URLlist.

Diagnostic Steps

Enable client side TRACE level logging for the following log category:

  • org.jboss.ejb.client
  • org.xnio.nio

A log snippet from the client would look similar to:

12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Selected on sun.nio.ch.WindowsSelectorImpl@7909e3d0
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBInvocationHandler] (main) Calling invoke(module = /reproducer/RemoteReferenceDataImpl, strong affinity = None, weak affinity = None): 
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Selected key sun.nio.ch.SelectionKeyImpl@4386f16 for java.nio.channels.SocketChannel[connected local=windows-machine/10.10.10.2:53297 remote=/10.10.10.1:8180]
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (main) sendRequest: calling interceptor: org.jboss.ejb.client.TransactionInterceptor@75c072cb
12:44:59,493 TRACE [org.jboss.logging.DelegatingBasicLogger] (XNIO-1 I/O-1) Calling handleReady key 4 for java.nio.channels.SocketChannel[connected local=windows-machine/10.10.10.2:53297 remote=/10.10.10.1:8180]
12:44:59,493 DEBUG [org.jboss.ejb.client.TransactionInterceptor] (main) TransactionEJBClientInterceptor: calling handleInvocation, context transaction = null, transaction policy = SUPPORTS
12:44:59,493 TRACE [org.xnio.ChannelListeners] (XNIO-1 I/O-1) Invoking listener org.jboss.remoting3.remote.RemoteConnection$RemoteWriteListener@6c5c3933 on channel org.xnio.conduits.ConduitStreamSinkChannel@26d40940
12:44:59,493 DEBUG [org.jboss.ejb.client.TransactionInterceptor] (main) TransactionEJBClientInterceptor: calling handleInvocation, no context transaction; using caller transaction = null
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@7909e3d0 (with timeout)
12:44:59,493 DEBUG [org.jboss.ejb.client.TransactionInterceptor] (main) TransactionEJBClientInterceptor: Calling  handleInvocation: setting context transaction: transaction = null
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Select, queue is empty
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (main) sendRequest: calling interceptor: org.jboss.ejb.client.NamingEJBClientInterceptor@1f1c7bf6
12:44:59,493 DEBUG [org.jboss.ejb.client.NamingEJBClientInterceptor] (main) NamingEJBClientInterceptor: calling handleInvocation: setting destination
12:44:59,493 DEBUG [org.jboss.ejb.client.NamingEJBClientInterceptor] (main) NamingEJBClientInterceptor: calling setNamingDestination: providerURIs = [remote+http://10.10.10.1:8080, remote+http://10.10.10.1:8180], invocationContext type = org.jboss.ejb.client.EJBClientInvocationContext
12:44:59,493 DEBUG [org.jboss.ejb.client.NamingEJBClientInterceptor] (main) NamingEJBClientInterceptor: setting destination: (size > 1), destination = remote+http://10.10.10.1:8080
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (main) sendRequest: calling interceptor: org.jboss.ejb.client.DiscoveryEJBClientInterceptor@214b199c
12:44:59,493 DEBUG [org.jboss.ejb.client.DiscoveryEJBClientInterceptor] (main) DiscoveryEJBClientInterceptor: calling handleInvocation - destination already discovered (destination = remote+http://10.10.10.1:8080)
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (main) sendRequest: calling interceptor: org.jboss.ejb.client.TransactionPostDiscoveryInterceptor@20d3d15a
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (main) sendRequest: calling interceptor: org.jboss.ejb.protocol.remote.RemotingEJBClientInterceptor@55ca8de8
12:44:59,493 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (main) sendRequest: setting receiver, strong affinity = None, weak affinity = None, remote destination is: remote+http://10.10.10.1:8080
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Selected on sun.nio.ch.WindowsSelectorImpl@7909e3d0
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Running task org.xnio.nio.WorkerThread$SynchTask@5de06685
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@7909e3d0 (with timeout)
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (main) Asynchronous connect
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Select, queue is empty
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Selected on sun.nio.ch.WindowsSelectorImpl@7909e3d0
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@7909e3d0 (with timeout)
12:44:59,493 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Select, queue is empty
12:45:00,585 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Selected on sun.nio.ch.WindowsSelectorImpl@7909e3d0
12:45:00,585 TRACE [org.xnio.nio.WorkerThread] (XNIO-1 I/O-1) Selected key sun.nio.ch.SelectionKeyImpl@304bb45b for java.nio.channels.SocketChannel[connection-pending remote=/10.10.10.1:8080]
12:45:00,585 TRACE [org.jboss.logging.DelegatingBasicLogger] (XNIO-1 I/O-1) Calling handleReady key 8 for java.nio.channels.SocketChannel[connection-pending remote=/10.10.10.1:8080]
12:45:00,585 TRACE [org.xnio.nio.WorkerThread$ConnectHandle] (XNIO-1 I/O-1) ConnectHandle.handleReady Exception, java.net.ConnectException: Connection refused: no further information
12:45:00,585 TRACE [org.xnio.nio.WorkerThread$ConnectHandle] (XNIO-1 I/O-1) !OK, closing connection
12:45:00,585 TRACE [org.xnio.IoUtils] (XNIO-1 I/O-1) Closing resource org.xnio.nio.NioSocketStreamConnection@637467ac
12:45:00,585 DEBUG [org.jboss.ejb.client.DiscoveryEJBClientInterceptor] (XNIO-1 task-1) DiscoveryEJBClientInterceptor: blacklisting destination (locator = StatelessEJBLocator for "/reproducer/RemoteReferenceDataImpl", view is interface org.jboss.reproducer.ejb.RemoteReferenceData, affinity is None, weak affinity = None, missing target = remote+http://10.10.10.1:8080)
12:45:00,585 TRACE [org.xnio.nio.NioHandle] (XNIO-1 I/O-1) Cancelling key sun.nio.ch.SelectionKeyImpl@304bb45b of java.nio.channels.SocketChannel[closed] (same thread)
12:45:00,585 DEBUG [org.jboss.ejb.client.EJBClientInvocationContext] (XNIO-1 task-1) Requesting retry of invocation!

Here the 1 second delay can be seen in the org.xnio.nio logging at 12:44:59,493 with a subsequent logging at 12:45:00,585.

SBR
Product(s)
Components
Category
Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.