4 Replies Latest reply on Aug 1, 2006 10:37 AM by Robert Schröder

    Delay in getting Server response

    Robert Schröder Newbie

      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).

        • 1. Re: Delay in getting Server response
          jaikiran pai Master

           

          "rschroeder" wrote:

          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).


          Have a look at:

          http://wiki.jboss.org/wiki/Wiki.jsp?page=ConfigurePorts

          http://wiki.jboss.org/wiki/Wiki.jsp?page=UsingJBossBehindAFirewall



          • 2. Re: Delay in getting Server response
            Robert Schröder Newbie

            This is a continuation of the original posting:

            Through additional logging we found RMI consuming a lot of time of the call to the server.

            The following log snippet shows a call to the JBoss JNDI - it took 7 seconds to find the proxy interfaces via classloader.

            
            08.06 10:05:41,390[DEBUG][][AWT-EventQueue-0][EjbHelper] - cout => [1149753941390] javax.naming.Context.lookup(DE.data_experts.jwam.domainvalue.ejb.DvLoaderEJB)
            
            [..]
            
            08.06 10:05:41,421[INFO ][][AWT-EventQueue-0][rmi] - 08.06.2006 10:05:41 sun.rmi.server.LoaderHandler loadProxyClass
            FEIN: AWT-EventQueue-0: interfaces = [DE.data_experts.jwam.domainvalue.ejb.DvLoaderEJBHome, javax.ejb.Handle], codebase = "http://AS2:11702/", defaultLoader = com.sun.jnlp.JNLPClassLoader@64f6cd
            
            08.06 10:05:41,421[INFO ][][AWT-EventQueue-0][rmi] - 08.06.2006 10:05:41 sun.rmi.server.LoaderHandler loadProxyClass
            FEINER: AWT-EventQueue-0: (thread context class loader: com.sun.jnlp.JNLPClassLoader@64f6cd)
            
            08.06 10:05:41,734[INFO ][][RMI ConnectionExpiration-[test.com:10742]][rmi] - 08.06.2006 10:05:41 sun.rmi.transport.tcp.TCPChannel$Reaper run
            FEINER: RMI ConnectionExpiration-[test.com:10742]: wake up
            
            08.06 10:05:46,843[INFO ][][RMI ConnectionExpiration-[test.com:12702,DE.data_experts.util.net.CompressingSocketFactory@c90e8007]][rmi] - 08.06.2006 10:05:46 sun.rmi.transport.tcp.TCPChannel$Reaper run
            FEINER: RMI ConnectionExpiration-[test.com:12702,DE.data_experts.util.net.CompressingSocketFactory@c90e8007]: wake up
            
            08.06 10:05:48,187[INFO ][][AWT-EventQueue-0][rmi] - 08.06.2006 10:05:48 sun.rmi.server.LoaderHandler loadProxyClass
            FEINER: AWT-EventQueue-0: proxy interfaces found via defaultLoader, defined by [com.sun.jnlp.JNLPClassLoader@64f6cd, com.sun.jnlp.JNLPClassLoader@64f6cd]
            
            08.06 10:05:48,187[INFO ][][AWT-EventQueue-0][rmi] - 08.06.2006 10:05:48 sun.rmi.server.LoaderHandler loadProxyClass
            FEINER: AWT-EventQueue-0: proxy class defined by sun.rmi.server.LoaderHandler$Loader@82d210["http://AS2:11702/"]
            
            08.06 10:05:48,187[INFO ][][AWT-EventQueue-0][rmi] - 08.06.2006 10:05:48 sun.rmi.server.LoaderHandler loadClass
            FEIN: AWT-EventQueue-0: name = "java.lang.reflect.Proxy", codebase = "http://AS2:11702/", defaultLoader = com.sun.jnlp.JNLPClassLoader@64f6cd
            
            [..]
            
            08.06 10:05:48,343[DEBUG][][AWT-EventQueue-0][EjbHelper] - cin => [1149753941390] javax.naming.Context.lookup(DE.data_experts.jwam.domainvalue.ejb.DvLoaderEJB)
            
            


            Any hints what could cause the problem?
            RMI? JBoss4? Webstart and it's JNLPClassloader? Some network problem?

            Robert

            • 3. Re: Delay in getting Server response
              Robert Schröder Newbie

              I think I identified the cause of the delay: When loading a proxy class, rmi logging says that "http://AS2:" is used as codebase.
              But the hostname of the machine running JBoss 4 is "as2.sub1.sub2.sub3.test.com".

              I started JBoss with the two parameters -Djava.rmi.server.hostname=as2.sub1.sub2.sub3.test.com -Djava.rmi.server.useLocalHostname=false
              suggested at this site http://wiki.jboss.org/wiki/Wiki.jsp?page=UsingJBossBehindAFirewall - but the slowdown doesn't disappear.
              Moreover, when loading a proxy class "http://AS2:" is still used.
              I expected to see something like "http://as2.sub1.sub2.sub3.test.com:" used as codebase.

              Do I also have to set provider URL with jnp protocol?
              What else could cause the trouble.