Re: dirty socket growth problem

Peter/all,

Sorry for my delay in answering.

Actually to be honest I never heard of 'lsof -p' before one of our
networking people showed me.  I used to use netstat all the time but it does
not show these sockets (not sure what state they are in).

BTW:  On solaris the lsof shows something slightly different to linux:

java    4928 root   30u  IPv4 0x3000ea979a8       0t0    TCP *:* (IDLE)
java    4928 root   31u  IPv4 0x3000a8407d8       0t0    TCP *:* (IDLE)
java    4928 root   32u  IPv4 0x3000ea97ca8       0t0    TCP *:* (IDLE)
java    4928 root   33u  IPv4 0x3000ace16f0       0t0    TCP *:* (IDLE)
java    4928 root   34u  IPv4 0x3000ea973a8       0t0    TCP *:* (IDLE)
java    4928 root   35u  IPv4 0x3000e848630       0t0    TCP *:* (IDLE)
java    4928 root   36u  IPv4 0x3000e849530       0t0    TCP *:* (IDLE)
etc...

The problem seems to happen on the server side but since all our processes
are communicating I have not done any test to prove it either way (Other
than noticing the growth as soon as I see the dirty method called).

The exception was basically a "cannot create socket exception" although we
are doing a ping (there is some history behind this code but it is not
really relevant to this problem):
java.rmi.ConnectIOException: Exception creating connection to: 192.168.1.48;
nested exception is:
        java.io.IOException: Cannot ping any host
        at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:580)
        at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
        at
sun.rmi.transport.tcp.TCPChannel.newConnection(TCPChannel.java:171)
        at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:101)
        at com.truetel.cluster.ClusterHostBase_Stub.notify(Unknown Source)
-PLUS-
java.net.SocketException: Too many open files
        at java.net.PlainDatagramSocketImpl.datagramSocketCreate(Native
Method)
        at
java.net.PlainDatagramSocketImpl.create(PlainDatagramSocketImpl.java:53)
        at java.net.DatagramSocket.createImpl(DatagramSocket.java:289)
        at java.net.DatagramSocket.<init>(DatagramSocket.java:130)
        at com.truetel.tcore.util.Pinger.doPing(UdpPing.java:38)
        at com.truetel.tcore.util.UdpPing.pingHost(UdpPing.java:200)
        at
com.truetel.cluster.MyClientSocketFactory.createSocket(MyClientSocketFactory
.java:73)
        at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:562)
        at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)

[The stack trace above shows that it is calling our Factory - however this
is when the problem manifested itself.  Before calling our Factory the
sockets will keep growing.  Please see my note below regarding calling our
createSocket method].

It occurred when the number of open sockets reached about 1000 (on linux).
On solaris this just seems to grow and grow without any side effect!

>> You mean that the growth does not correspond to invocations of your
factory's createSocket method?
Yes (there are a couple of calls at the start of the program but once up and
running no more calls).  I was surprised at this as I much prefer blaming my
own code to other peoples!  So I do not know who is creating these sockets
(I searched the rest of our code and cannot find any other places we create
sockets).  Also as I mentioned in the original post if we run the code in
jdk1.3 the problem does not occur.

As far as debug I turned on everything I could think of:

-Djava.rmi.server.logCalls=true \
-Djava.rmi.client.logCalls=true \
-Dsun.rmi.server.exceptionTrace=true \
-Dsun.rmi.transport.logLevel=VERBOSE \
-Djava.rmi.ssl.debug=true \

We are still testing but it seems I can slow down the problem by increasing
the lease time (yes I know this will cause memory leak problems if we are
passing lots of objects around):

-Djava.rmi.dgc.leaseValue=86400000 \

At present I do not have a simple test program.  I plan to create on after
Christmas (as I am off on vacation!).  Once I get back if the test program
duplicates the problem I will send it to the RMI list.

Thanks for your help,

Stuart


-----Original Message-----
From: Peter Jones - JavaSoft East [mailto:[email protected]]
Sent: Thursday, December 08, 2005 3:38 AM
To: [email protected]
Subject: Re: dirty socket growth problem

> I am using jdk1.4 to run an RMI program and I have a socket growth
> problem on linux and solaris (I have not tried windows).  The
> problem is that every 5 minutes we see an increase in sockets using
> the following command (as root):
>
> /usr/sbin/lsof -p 9706
>
> java    9706 root  594u  sock    0,0           618721 can't identify
protocol
> java    9706 root  595u  sock    0,0           623390 can't identify
protocol
> java    9706 root  596u  sock    0,0           618749 can't identify
protocol
> java    9706 root  598u  sock    0,0           623394 can't identify
protocol
> etc...

I'm not quite sure how to interpret that.  Does netstat show an
increasing number of ESTABLISHED connections (from 192.168.1.47)?  Do
you notice this effect in both the client (remote caller) and server
(remote object) processes?  (Or are they in the same process?)

> On solaris I think this just keeps growing and growing (but does not
> die).  On linux it gets to a certain size and then has a problem.

What problem, specifically?  Do you have a complete exception trace?

> We are using our own socket factories and so I added debug to figure
> out why we were creating so many sockets.  Anyway it turns out it
> was not our socket factory.

You mean that the growth does not correspond to invocations of your
factory's createSocket method?

> I turned on the RMI debug and discovered the sockets increase every
> time the lease is renewed:
>
> ...
> FINER: RMI TCP Connection(2)-192.168.1.47: call dispatcher
> Dec 5, 2005 3:42:29 PM sun.rmi.server.UnicastServerRef logCall
> FINER: RMI TCP Connection(2)-192.168.1.47: [192.168.1.47:
sun.rmi.transport.DGCImpl[0:0:0, 2]: java.rmi.dgc.Lease
dirty(java.rmi.server.ObjID[], long, java.rmi.dgc.Lease)]
> ...

What logging output do you see on the client side, with the
sun.rmi.transport.tcp logger enabled?
        http://java.sun.com/j2se/1.4.2/docs/guide/rmi/logging.html
For example, logging messages like "create connection", "connection
timeout expired", etc.?

> We tried testing the code with jdk1.3.1_02 and this problem does not
> occur.  Also on jdk1.4.1_07 I can prevent the sockets growing by
> just increasing the lease time to some very large number.

Do you have a small test case that exhibits this effect, with command
lines, etc.?

-- Peter

===========================================================================
To unsubscribe, send email to [email protected] and include in the body
of the message "signoff RMI-USERS".  For general help, send email to
[email protected] and include in the body of the message "help".

For a list of frequently asked RMI questions please refer to:
http://java.sun.com/j2se/1.3/docs/guide/rmi/faq.html

To view past RMI-USERS postings, please see:
http://archives.java.sun.com/archives/rmi-users.html

===========================================================================
To unsubscribe, send email to [email protected] and include in the body
of the message "signoff RMI-USERS".  For general help, send email to
[email protected] and include in the body of the message "help".

For a list of frequently asked RMI questions please refer to:
http://java.sun.com/j2se/1.3/docs/guide/rmi/faq.html

To view past RMI-USERS postings, please see:
http://archives.java.sun.com/archives/rmi-users.html