slow lookup, delay 3 seconds

[haribo]

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.

[haribo]

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