1 Reply Latest reply on Sep 4, 2008 5:06 AM by Harald Hartmann

    slow lookup, delay 3 seconds

    Harald Hartmann Newbie

      Hello Everybody,

      in our productive enviroment, we running a JBOSS 4.0.5 GA as server and JRE1.6.0.01 as clients. Since a few days, some clients take a long time for the first lookup to an EJB. We find out, that for each node in the cluster we takes down, the first lookup takes 3 seconds fewer.

      tcpdump with the last active node:
      12:30:09.906709 IP W1OG304570.2051 > JBOSS-05.1099: S 3609508404:3609508404(0) win 64512 <mss 1460,nop,nop,sackOK>
      12:30:09.907384 IP JBOSS-05.1099 > W1OG304570.2051: S 1701190293:1701190293(0) ack 3609508405 win 5840 <mss 1460,nop,nop,sackOK>
      12:30:09.907432 IP W1OG304570.2051 > JBOSS-05.1099: . ack 1 win 64512
      12:30:09.907726 IP JBOSS-05.1099 > W1OG304570.2051: P 1:5(4) ack 1 win 5840
      12:30:09.908103 IP JBOSS-05.1784772193 > W1OG304570.2051: 355 proc-1651139939
      12:30:09.908262 IP W1OG304570.2051 > JBOSS-05.1099: . ack 361 win 64153
      12:30:09.988872 IP W1OG304570.2052 > JBOSS-05.1098: S 1598309292:1598309292(0) win 64512 <mss 1460,nop,nop,sackOK>
      12:30:09.989133 IP JBOSS-05.1098 > W1OG304570.2052: S 1706430601:1706430601(0) ack 1598309293 win 5840 <mss 1460,nop,nop,sackOK>
      12:30:09.989290 IP W1OG304570.2052 > JBOSS-05.1098: . ack 1 win 64512
      12:30:12.985180 IP W1OG304570.2052 > JBOSS-05.1098: P 1:8(7) ack 1 win 64512

      12:30:12.985231 IP JBOSS-05.1098 > W1OG304570.2052: . ack 8 win 5840
      12:30:12.985501 IP JBOSS-05.1098 > W1OG304570.2052: P 1:20(19) ack 8 win 5840
      12:30:12.986998 IP W1OG304570.2052 > JBOSS-05.1098: P 8:26(18) ack 20 win 64493
      ...

      Switching from port 1099 to port 1100 doesn't matter. After the first lookup, it's running fast

      Seems to be a client problem, but we test this with identical clients installed by the same image. We also copied the jre-dir from a client without the problem to one with the problem, without any effect.

      any clues?

      Kind Regards.

        • 1. Re: slow lookup, delay 3 seconds
          Harald Hartmann Newbie

          02.09.2008 15:59:43 sun.rmi.transport.tcp.TCPEndpoint
          FEIN: main: localHostKnown = true, localHost = 138.33.0.204
          02.09.2008 15:59:43 sun.rmi.transport.tcp.TCPTransport
          FEIN: main: Version = 2, ep = [138.33.0.204:0]
          02.09.2008 15:59:43 sun.rmi.transport.tcp.TCPEndpoint getLocalEndpoint
          FEIN: main: created local endpoint for socket factory null on port 0
          02.09.2008 15:59:43 sun.rmi.transport.tcp.TCPChannel createConnection
          FEIN: main: create connection
          02.09.2008 15:59:43 sun.rmi.transport.tcp.TCPEndpoint newSocket
          FEINER: main: opening socket to [138.33.5.51:1101]
          02.09.2008 15:59:43 sun.rmi.transport.proxy.RMIMasterSocketFactory createSocket
          FEIN: main: host: 138.33.5.51, port: 1101
          02.09.2008 15:59:46 sun.rmi.transport.tcp.TCPChannel createConnection
          FEINER: main: server suggested 138.33.0.204:2297

          02.09.2008 15:59:46 sun.rmi.transport.tcp.TCPChannel createConnection
          FEINER: main: using 138.33.0.204:0
          02.09.2008 15:59:46 sun.rmi.server.UnicastRef logClientCall
          FEINER: main: outbound call: [endpoint:[138.33.5.51:1101](remote),objID:[0:0:0, 2]] : sun.rmi.transp
          ort.DGCImpl_Stub[0:0:0, 2]: java.rmi.dgc.Lease dirty(java.rmi.server.ObjID[], long, java.rmi.dgc.Lea
          se)
          02.09.2008 15:59:46 sun.rmi.transport.StreamRemoteCall
          FEINER: main: write remote call header...