opuscula orbis

Client Side Transport Timeouts and Retries A user recently complained about ORB retry behavior (among other issues).  The following problems are mentioned:

• Too much log output when a host/port is not reachable.

The ORB is logging connectFailure methods, producing a lot of output that looks something like:

18.04.2007 12:26:37 com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl <init>
WARNING: "IOP00410201: (COMM_FAILURE) Connection failure: socketType: IIOP_CLEAR_TEXT; hostname: localhost; port: 3700"
org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 201 completed: No
at com.sun.corba.ee.impl.logging.ORBUtilSystemException.connectFailure(ORBUtilSystemException.java:2348)
at com.sun.corba.ee.impl.logging.ORBUtilSystemException.connectFailure(ORBUtilSystemException.java:2369)
at com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl.<init>(SocketOrChannelConnectionImpl.java:212)
at com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl.<init>(SocketOrChannelConnectionImpl.java:225)
at com.sun.corba.ee.impl.transport.SocketOrChannelContactInfoImpl.createConnection(SocketOrChannelContactInfoImpl.java:104)

• The ORB transport timeout parameters are not adequately configurable.  In particular, the ORB request timeout cannot be set.

We've known for some time that there were some issues with ORB retries. Recently someone filed a high priority bug (6546045, which is a duplicate of 6394769) complaining about too many retries when sending a request to a bad host and port.  I wrote a simple test to reproduce this, and found that the ORB was re-trying 56000 times per minute on my test machine (JDK 1.5_10, Ubuntu 6.06, Athlon 64 3500+ with 2 GB RAM).

The problem is that the ORB needs to retry the entire list of endpoints in a cluster, and wrap from the end of the list to the beginning. The old code intended to use a simple exponential backoff in this case, but it ONLY applied the wait with backoff when the error was either a TRANSIENT or a COMM_FAILURE connectionRebind (both COMPLETED_NO of course). Any other COMM_FAILURE COMPLETED_NO was treated as a "try the next endpoint" kind of retry. Now, this is good in the cluster case, because we want to try the next endpoint quickly. But we also don't want to try all of the endpoints over and over again if they all fail (or, the same single endpoint over and over again, which is what happens in this bug).

The fix is to introduce another use of TcpTimeouts here, and to record the failed endpoints in a list, until we find that the next endpoint to try is already in the list. In that case, we clear the list, sleep for the next timeout, and then start retrying again. That way, we try every endpoint once quickly, and then sleep until we try again, or timeout.  This reduces the number of retries by a factor of at least 1000 with ony a minor impact on responsiveness in the (usually) rare case of a transient failure.

There are a number of ORB config parameters in com.sun.corba.ee.impl.orbutil.ORBConstants (note that this is the GlassFish ORB, not the JDK ORB: see this blog entry).  The constants relevant to transport timeouts are:

• TRANSPORT_TCP_TIMEOUTS_PROPERTY
  This controls the retry behavior when the ORB is reading data and does not get all of the data at once. It is an instance of TcpTimeouts.  The defaults are 2000:6000:20.
  

• TRANSPORT_TCP_CONNECT_TIMEOUTS_PROPERTY
  This is the one relevant to this discussion. It controls how the ORB behaves on the client side when attempting to connect to an IOR (the wire rep of an EJB reference).  This is also an instance of TcpTimeouts.  The defaults are 250:60000:100:5000.
  

• WAIT_FOR_RESPONSE_TIMEOUT
  This controls how long the client waits for a response AFTER successfully sending a request. The default is 30 minutes.
  

Both TcpTimeouts use the same syntax for configuration:

initial:max:backoff[:maxsingle] (a series of 3 or 4 positive decimal integers separated by :)

where:

• initial is the first timeout in milliseconds
• max is the maximum wait time (before the last wait, which can go over this time) in milliseconds
• backoff is the backoff factor by which the timeout is increased each time (the multiplication is actually by (backoff+100)/100, so 20 is 1.2 and 100 is 2, but we avoid any use of floating point here). This should normally be somewhere between 10 and 100.
  
• maxsingle is the maximum single wait time.  This is optional, and defaults to Integer.MAX_VALUE if not defined.
  

This works as follows:

1. The first timeout last for initial milliseconds.
2. Each subsequent timeout is obtained from the previous by multiplying by the backoff factor (as explained above)
3. No timeout can exceed maxsingle milliseconds: once this value is reached, any subsequent timeouts have the same value.
4. The total time spent before the last timeout is less than max.  Note that the last timeout may cause the total time to exceed max.
   

I've removed the old COMMUNICATIONS_RETRY_TIMEOUT. These changes will be available in GlassFish v2 after the next ORB integration.  I think this will be b47, as  we've probably missed the integration deadline for b46.

Note that these settings are global: once set, the control every request sent to every object reference managed by the ORB instance.  Fine grained control over timeouts is possible, but would require new APIs for RMI-IIOP.

---

It now looks like it will be b48 (not b47) when this change is integrated.  The ORB integration is taking longer than expected.