Delay in getting Server response
We got a serious and mysterious problem:
Recently we switched from JBoss 2.4.3 to JBoss 4.0.3SP1.
Our tests were fine and we shipped our product with JBoss 4 to our customers.
All customers are happy with the new release except one.
This one customer reported performance problems (The problems are not reproducible in our test systems and other customers do not have these performance problems).
After a lot of searching we found a delay in communication between client and server. This delay happens when doing a Context lookup to get a reference to an EJB from JNDI and when calling #create() on an EJBObject: On server side the request for creating an EJB instance is handled fast but it takes a while until the call returns on the client.
We added a LogInterceptor an client and server side and these are typical log statements:
Client 17:05:34,339 [EjbHelper] - start: findRemoteObject(profi.util.dokument.ejb.DvLoaderEJBHome) 17:05:41,168 [EjbHelper] - end: findRemoteObject(profi.util.dokument.ejb.DvLoaderEJBHome) 17:05:41,168 [EjbHelper] - #createSessionBean start DE.data_experts.profi.util.dokument.ejb.DvLoaderEJBHome.create() 17:05:41,168 [ClientLogInterceptor] - cout => [1147187141168] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJBHome.create() 17:05:51,199 [ClientLogInterceptor] - cin => [1147187141168] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJBHome.create() 17:05:51,199 [EjbHelper] - #createSessionBean end DE.data_experts.profi.util.dokument.ejb.DvLoaderEJBHome.create() Server 17:05:41,176 DEBUG [DE.data_experts.util] Compressing Socket Factory accepting connection @ port 4219 from adress /11.8.27.194 17:05:42,187 INFO [LogInterceptor] in => [1147187141168] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJBHome.create() 17:05:42,187 INFO [LogInterceptor] out => [1147187141168] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJBHome.create()
(What you see are logs for retrieving an EJB: #findRemoteObject does a JNDI lookup. After getting an object from JNDI #create is called on this object.)
Calling an action on an obtained EJB is on the other hand really fast - just a few milliseconds are gone by.
Client 17:05:51,199 [ClientLogInterceptor] - cout => [1147187151199] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJB.getDokumentartClasses() 17:05:53,089 [ClientLogInterceptor] - cin => [1147187151199] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJB.getDokumentartClasses() Server 17:05:53,041 INFO [org.jboss.ejb.plugins.LogInterceptor] in => [1147187151199] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJB.getDokumentartClasses() 17:05:53,042 INFO [org.jboss.ejb.plugins.LogInterceptor] out => [1147187151199] DE.data_experts.profi.util.dokument.ejb.DvLoaderEJB.getDokumentartClasses()
(The delay between client out and server in is a coincidence - but I am providing this for a full example.)
So it seems that at doing JNDI lookup and getting an EJB instance we lost time on the net.
Our customers checked his firewall configuration and said that all was fine.
Yet our customer runs our product with JBoss 2 on the same machine as the JBoss 4 version and the delays are just appearing in the JBoss 4 system.
Any hints what could cause such a delay?
Robert
PS: Is there a way to configure the range of ports used for RMI? It seems that the PooledInvoker uses a port range starting at 4000 - but it should use a higher lower limit (starting at 10.000).
