dev@glassfish.java.net

JAX-WS client memory usage

From: Marshall Pierce <marshall_at_genius.com>
Date: Mon, 23 Aug 2010 15:05:51 -0700

I'm seeing pretty high memory usage with idle JAX-WS client bindings
using 2.1.7. (I haven't upgraded to 2.2 because of the need to deploy
jars into the jvm endorsed dir.)

The app in question is a daemon that downloads data from many different
Salesforce organizations using the Partner WSDL. (Salesforce is a
multi-tenant system, so if you were to buy their service you would be
one of many orgs that reside on the same server cluster.) Because our
systems talk to many different orgs, we cache several bindings for each org.

I have a heap dump from when the app was idle. (I abused the GC button
in jconsole until memory usage stabilized just before I took the heap
dump, and I'm pretty sure I only included live objects in the heap dump
anyway.) There were 3,056 cached bindings and the heap dump is 5.3GB.

jhat's basic data about the heap dump is pretty telling. The first
several dozen classes in the instance count view are all
com.sun.xml.bind.v2. Here's the top of the instance count view:

2060410 com.sun.xml.bind.v2.runtime.Name
1825554 com.sun.istack.FinalArrayList
1782624 com.sun.xml.bind.v2.util.QNameMap$Entry
1489196 com.sun.xml.bind.v2.runtime.unmarshaller.ChildLoader
1344078 com.sun.xml.bind.v2.model.impl.FieldPropertySeed
1344078
com.sun.xml.bind.v2.model.impl.RuntimeClassInfoImpl$RuntimePropertySeed
1344078 com.sun.xml.bind.v2.runtime.reflect.Accessor$FieldReflection
1325125 com.sun.xml.bind.v2.model.impl.ElementPropertyInfoImpl$1
1325125 com.sun.xml.bind.v2.model.impl.RuntimeElementPropertyInfoImpl
1325125 com.sun.xml.bind.v2.model.impl.RuntimeTypeRefImpl
1113715 com.sun.xml.bind.v2.runtime.output.Encoded
883400 com.sun.xml.bind.v2.model.impl.RuntimeEnumConstantImpl
760363 com.sun.xml.bind.v2.runtime.unmarshaller.LeafPropertyLoader
725667 com.sun.xml.bind.v2.runtime.property.TagAndType

2 million Names seems a little excessive for a completely idle app, even
though at 39 bytes each that doesn't add up to all *that* much memory.

One interesting thing is that the idle memory usage increases as we
increase the amount of data we get per call from Salesforce. One of the
calls (retrieve()) lets you specify the list of Ids that you want the
data for with a max of 2000 Ids. We want to use as many Ids as possible
in each call to minimize the number of API calls made since those are
metered by Salesforce. We used to use 500 per call, but recently
increased it to use fewer API calls. When we tried to download 2000 per
retrieve(), we quickly got an OOME. We're currently using 1000 per call.
  That OOME (always fun on production...) is what prompted me to start
looking into JAX-WS's memory usage.

No doubt you guys will have further suggestions for tracking down the
source of the issue, but I did find one interesting thing just poking
around in jhat. The highest instance count for any clas in our package
(com.genius) was for a class that JAX-WS generated from the Partner
WSDL. It happened to be QueryAll which is used to house the SOQL (it's
like SQL but for Salesforce objects) statement passed to the queryAll
API call. The interesting part is the reference chain from the rootset
to a particular instance (chosen randomly -- other instances had similar
or identical chains).

--> com.genius.crm.sf.conn.ConnectionImpl_at_0x7f06ba6f9400 (81 bytes)
(field binding:)
--> $Proxy50_at_0x7f06ba6f95f8 (24 bytes) (field h:)
--> com.sun.xml.ws.client.sei.SEIStub_at_0x7f06ba6f9610 (128 bytes) (field
responseContext:)
--> com.sun.xml.ws.client.ResponseContext_at_0x7f07478cd2c8 (48 bytes)
(field packet:)
--> com.sun.xml.ws.api.message.Packet_at_0x7f07478cd2f8 (145 bytes) (field
satellites:)
--> com.sun.istack.FinalArrayList_at_0x7f07478cd390 (32 bytes) (field
elementData:)
--> [Ljava.lang.Object;@0x7f07478cd3b8 (96 bytes) (Element 1 of
[Ljava.lang.Object;@0x7f07478cd3b8:)
-->
com.sun.xml.ws.transport.http.client.HttpResponseProperties_at_0x7f07478cd420
(32 bytes) (field deferedCon:)
-->
com.sun.xml.ws.transport.http.client.HttpClientTransport_at_0x7f07478cd440
(93 bytes) (field context:)
--> com.sun.xml.ws.api.message.Packet_at_0x7f07478da2c8 (145 bytes) (field
message:)
--> com.sun.xml.ws.message.jaxb.JAXBMessage_at_0x7f07478da3f0 (112 bytes)
(field jaxbObject:)
--> com.genius.crm.sf.jaxwsstub.QueryAll_at_0x7f07478da528 (24 bytes)

com.genius.crm.sf.conn.ConnectionImpl is my own wrapper around the
JAX-WS-generated binding (the $Proxy50 object).

It looks like the binding is holding on to too much data about the last
request that was performed on it. (If you doubt the idle-ness of the
app, this particular connection object was in the connection pool, so
you may be doubly confident that this one was not in use.)

I'm happy to enable extra logging, etc to help track this down. Memory
usage is currently the #1 bottleneck facing this app.