|
Description
|
.
When using RMI, we are experiencing very high object
creation/deletion rates (e.g. 35,000 per second)
resulting in a very heavy garbage collection
load. This appears to be caused by the
use of a new ObjectOutputStream for each RMI
call.
---------------------------------------------------
The constructor of StreamRemoteCall calls the method
getOutputStream which creates a new instance of
sun.rmi.transport.ConnectionOutputStream which is
a subclass of sun.rmi.server.MarshallOutputStream
which is a subclass of java.io.ObjectOutputStream
- which is where the fun begins.
The instance of the StreamRemoteCall appears to be
unreferenced immediatly after the dispatch operation
which leads to the ObjectOutputStream being
dereferenced. The problem is that to prevent writing
class/instance information into a stream twice,
ObjectOutputStream allocates three arrays (one of
100 Objects, one of 100 ints and the third of 101 ints).
For RMI these do not seem to be used and are allocated
and then immediately collected, which is a *huge*
performance hit.
Given that there are other objects allocated for the
general case, and that these objects are created at
the client, the server *and* the registry, each dispatch
operation is responsible for creating over 300 Objects and
over 600 primitives....
Here is some sample verbose GC output which confirms the
problem - note that the elapsed time from start to end is
less that 10 seconds....
<GC: managing allocation failure. need 408 bytes, type=1, action=1>
<GC: freeing class java.lang.Compiler>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: freeing class sun.security.provider.SHA>
<GC: unloaded and freed 3 classes>
<GC: freed 7498 objects, 658048 bytes in 57 ms, 78% free (658240/838856)>
<GC: init&scan: 49 ms, scan handles: 5 ms, sweep: 3 ms, compact: 0 ms>
<GC: managing allocation failure. need 1032 bytes, type=1, action=1>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: unloaded and freed 1 class>
<GC: freed 6882 objects, 636152 bytes in 8 ms, 78% free (660592/838856)>
<GC: init&scan: 0 ms, scan handles: 5 ms, sweep: 3 ms, compact: 0 ms>
<GC: managing allocation failure. need 1032 bytes, type=1, action=1>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: unloaded and freed 1 class>
<GC: freed 6863 objects, 632920 bytes in 9 ms, 78% free (660496/838856)>
<GC: init&scan: 0 ms, scan handles: 6 ms, sweep: 3 ms, compact: 0 ms>
<GC: managing allocation failure. need 1032 bytes, type=1, action=1>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: unloaded and freed 1 class>
<GC: freed 6698 objects, 630216 bytes in 8 ms, 78% free (658720/838856)>
<GC: init&scan: 0 ms, scan handles: 5 ms, sweep: 3 ms, compact: 0 ms>
<GC: managing allocation failure. need 1032 bytes, type=1, action=1>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: unloaded and freed 1 class>
<GC: freed 6934 objects, 630848 bytes in 8 ms, 78% free (660640/838856)>
<GC: init&scan: 0 ms, scan handles: 5 ms, sweep: 3 ms, compact: 0 ms>
<GC: managing allocation failure. need 1032 bytes, type=1, action=1>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: unloaded and freed 1 class>
<GC: freed 6849 objects, 632648 bytes in 8 ms, 78% free (660416/838856)>
<GC: init&scan: 0 ms, scan handles: 5 ms, sweep: 3 ms, compact: 0 ms>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: unloaded and freed 1 class>
<GC: freed 5293 objects, 485112 bytes in 14 ms, 78% free (662232/838856)>
<GC: init&scan: 0 ms, scan handles: 5 ms, sweep: 2 ms, compact: 7 ms>
(Review ID: 25927)
======================================================================
Additonal information from user, xxxxx@xxxxx 1998-03-05:
We now have separted out a test program to demonstrate
the problem.
Attatched are the four class files. Bind the
RmiServerImpl to a running registry and run the client with
java -verbosegc -noasyncgc RmiClient
There is a loop in the main() method of the client which controls the
number of dispatch operations that are sent - it is currently set to one.
Here is the GC output for the code as it stands, which implies that for a
single, simple RMI operation over 1100 Objects are allocated.....the
allocation rate does not appear to be linear with the number of dispatches,
but is still very heavy....
<GC: freeing class java.lang.Compiler>
<GC: freeing class sun.rmi.registry.RegistryImpl_Stub>
<GC: freeing class sun.security.provider.SHA>
<GC: unloaded and freed 3 classes>
<GC: freed 1129 objects, 53672 bytes in 10 ms, 79% free (667504/838856)>
<GC: init&scan: 0 ms, scan handles: 4 ms, sweep: 1 ms, compact: 5 ms>
|
