Re: DGCClient$EndpointEntry stuck

Paul Beadle <[email protected]>
Newsgroups gmane.comp.java.sun.rmi
Message-ID <LISTSERV%[email protected]> 
Thanks Peter.  I am still investigating whether it is possible that the
RMI client is inadvertently holding onto a remote reference, but it's
difficult because we cannot reproduce the problem in the Lab - so far we
are only seeing it at customer sites :¬(

In any case, the sockets should always close (yes, we do track socket
closures and we are not seeing them for the sockets in question).

Also, in any case we are not seeing the exponential hold-off feature.

Here is a list of some of the socket request data.  The timestamp is the
socket creation time:

Connected To 161.15.215.114 1066 2016 enc=false RMI RenewClean-
[C0117270:1066] Fri Nov 19 16:54:24 EST 2004 java.lang.Throwable   at
wigan.infrastruct.serviceutil.sktRecord.<init>(WgnSocket.java:416)   at
wigan.infrastruct.serviceutil.WgnSocket.<init>(WgnSocket.java:119)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.clean(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeCleanCalls
(DGCClient.java:619)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1600(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:533)   at java.lang.Thread.run(Thread.java:479)

Connected To 161.15.215.114 1066 1831 enc=false RMI RenewClean-
[C0117270:1066] Fri Nov 19 17:14:23 EST 2004 java.lang.Throwable   at
wigan.infrastruct.serviceutil.sktRecord.<init>(WgnSocket.java:416)   at
wigan.infrastruct.serviceutil.WgnSocket.<init>(WgnSocket.java:119)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.dirty(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeDirtyCall
(DGCClient.java:318)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1500(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:529)   at java.lang.Thread.run(Thread.java:479)

Connected To 161.15.215.114 1066 1124 enc=false RMI RenewClean-
[C0117270:1066] Fri Nov 19 17:34:23 EST 2004 java.lang.Throwable   at
wigan.infrastruct.serviceutil.sktRecord.<init>(WgnSocket.java:416)   at
wigan.infrastruct.serviceutil.WgnSocket.<init>(WgnSocket.java:119)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.clean(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeCleanCalls
(DGCClient.java:619)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1600(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:533)   at java.lang.Thread.run(Thread.java:479)

Connected To 161.15.215.114 1066 4240 enc=false RMI RenewClean-
[C0117270:1066] Fri Nov 19 17:54:23 EST 2004 java.lang.Throwable   at
wigan.infrastruct.serviceutil.sktRecord.<init>(WgnSocket.java:416)   at
wigan.infrastruct.serviceutil.WgnSocket.<init>(WgnSocket.java:119)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.dirty(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeDirtyCall
(DGCClient.java:318)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1500(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:529)   at java.lang.Thread.run(Thread.java:479)


I inserted 'guard' code to spot when lots of sockets are created to the
same destination and then refuse additional ones by throwing an
IOException in my socket constructor.  This is a snippet of the socket
creation details when the java gets into this state:


LIMITING CONNECTION Connected To 165.168.35.33 1053 0 enc=false RMI
RenewClean-[197426:1053] Wed Dec 08 18:02:01 EST 2004 java.lang.Throwable
 at wigan.infrastruct.serviceutil.sktRecord.<init>
(WgnSocket.java:421)   at wigan.infrastruct.serviceutil.WgnSocket.<init>
(WgnSocket.java:120)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.clean(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeCleanCalls
(DGCClient.java:619)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1600(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:533)   at java.lang.Thread.run(Thread.java:479)

LIMITING CONNECTION Connected To 165.168.35.33 1053 0 enc=false RMI
RenewClean-[197426:1053] Wed Dec 08 18:02:01 EST 2004 java.lang.Throwable
 at wigan.infrastruct.serviceutil.sktRecord.<init>
(WgnSocket.java:421)   at wigan.infrastruct.serviceutil.WgnSocket.<init>
(WgnSocket.java:120)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.dirty(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeDirtyCall
(DGCClient.java:318)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1500(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:529)   at java.lang.Thread.run(Thread.java:479)

LIMITING CONNECTION Connected To 165.168.35.33 1053 0 enc=false RMI
RenewClean-[197426:1053] Wed Dec 08 18:02:01 EST 2004 java.lang.Throwable
 at wigan.infrastruct.serviceutil.sktRecord.<init>
(WgnSocket.java:421)   at wigan.infrastruct.serviceutil.WgnSocket.<init>
(WgnSocket.java:120)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.clean(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeCleanCalls
(DGCClient.java:619)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1600(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:533)   at java.lang.Thread.run(Thread.java:479)

LIMITING CONNECTION Connected To 165.168.35.33 1053 0 enc=false RMI
RenewClean-[197426:1053] Wed Dec 08 18:02:01 EST 2004 java.lang.Throwable
 at wigan.infrastruct.serviceutil.sktRecord.<init>
(WgnSocket.java:421)   at wigan.infrastruct.serviceutil.WgnSocket.<init>
(WgnSocket.java:120)   at
wigan.infrastruct.serviceutil.CustomSocketFactory.createSocket
(CustomSocketFactory.java:198)   at
sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:494)   at
sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
 at sun.rmi.transport.tcp.TCPChannel.newConnection
(TCPChannel.java:169)   at sun.rmi.server.UnicastRef.newCall
(UnicastRef.java:313)   at sun.rmi.transport.DGCImpl_Stub.dirty(Unknown
Source)   at sun.rmi.transport.DGCClient$EndpointEntry.makeDirtyCall
(DGCClient.java:318)   at
sun.rmi.transport.DGCClient$EndpointEntry.access$1500(DGCClient.java:136)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:529)   at java.lang.Thread.run(Thread.java:479)

I'm not sure whether this effect isn't triggered by the choice of
exception I throw - perhaps if it was a java.rmi.ConnectException it would
trigger the exponential hold off and eventual halt?

Paul

On Fri, 10 Dec 2004 14:22:51 -0500, Peter Jones - JavaSoft East
<[email protected]> wrote:

>> I too am having problems with DGC threads, though in my case they
>> get stuck in endless loops creating sockets, eventually starving the
>> machine of resources.  The application uses socket factories (and
>> also subclasses Socket so I can track them) and of course has
>> hashCode and equals methods on the socket factory class.  The
>> machine where the problem has occurred is actually the server; lots
>> of clients make RMI calls to the server for info.  Separately, the
>> server connects to each client occasionally to pull data up (which
>> makes load management on the server much easier).  It is this
>> process that somehow triggers the 'runaway' socket creation process.
>> In the custom socket class, I log socket creation time and a stack
>> trace so I can see that sometimes a DGC thread on the server
>> (actually being an RMI client) creates sockets to a client (acting
>> as an RMI server) every 20 minutes.
>
>Recurring DGC "dirty" calls to an endpoint are expected while there
>are live remote references to remote objects at that endpoint in the
>local virtual machine (like this "server"), for renewing the DGC
>lease.  The interval is affected by the duration of the lease granted
>by the endpoint's VM, which can be controlled by the setting of the
>"java.rmi.dgc.leaseValue" system property in that VM:
>
>        http://java.sun.com/j2se/1.4/docs/guide/rmi/javarmiproperties.html
>
>> In one instance the interval was just seconds.
>
>If a DGC "dirty" call fails for some reason, it is retried (assuming
>at least the J2SE 1.3 implementation), first quickly, and then with an
>exponentially-increasing delay until eventually giving up-- at which
>point it should not be retried until a new remote reference with the
>same endpoint enters in the VM.
>
>> And the sockets don't get closed either,
>
>That would be a problem.  Do you also log invocations of close() on
>your custom socket class?  If so, you don't see any invocations of it
>from threads named "RMI ConnectionExpiration-[...]"?
>
>> so doing a netstat comes up with a long list of unconnected sockets.
>
>Could you be more specific?
>
>-- 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
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.