Daily Power Ups

Recent Posts Widget

Friday, August 9, 2013

Permgen crashes due to class loader leaks

Sometime back a colleague was running a performance test and the site was crashing due to an OOM situation.  However, they, not being performance focused, were having a tough time isolating the srouce of the crash.  So I volunteered to help and found that when the site was running it was overloading the permgen space causing the crash.  The permgen is where loaded classes are kept and sure enough if you watched the class graph in JConsole or VisualVM you would confirm that as the site ran the classes loaded were growing too fast for the permgen space to keep up with (in terms of collection) and that there was little to no unloading.  After investigating we found 2 different sites with similar issues in different area's and had to use 2 different methods to track down the root cause.  Here we've documented the processes uses.

In general the JAX-WS based implementations have the potential to leak if you are not declaring the interactions to the components as singletons.  JAXB is very notorious for this especially with regards to the JAXBContext where-in the classes are loaded/re-loaded into memory - see:http://stackoverflow.com/questions/3259291/do-i-have-a-jaxb-classloader-leak
PROCESS 1
The following is the process for debugging a classloader leak issue and was used to find class loader leaks on Client X, running an Oracle DB backend and Glassfish server.
Enable the following JVM Options:
-XX:+TraceClassLoading
-XX:+TraceClassUnloading
-XX:+PrintGCDetails

Assuming you can import the log statements into a DB for easier searching do the below, otherwise just examine the log file directly...
For loading into a DB
----------------------------------------------------

Now from the GC log file
Run a replace to remove the leading [
Run a regex replace to remove the "from"
     from .*$

Save the file as classLoader.csv
Open sql developer
Import the csv file to a table named CLASSLOADER
Name the field load_log and make sure it is 500 characters long
After the import, run this statement to see the class loader issues

select count(*), load_log from classloader
group by load_log
having count(*) > 1
ORDER BY COUNT(*) DESC
--------------------------------------------------------
Below is output that indicates a problem with a custom class on the site. These classes should have loaded once.
Loaded com.foobar.service.order.Result$JaxbAccessorF_description
    Loaded com.foobar.service.order.BillingInfo$JaxbAccessorF_city
    Loaded com.foobar.service.order.BillingInfo$JaxbAccessorF_zipCode
    Loaded com.foobar.service.order.Payment$JaxbAccessorF_cardNumber
    Loaded com.foobar.service.order.Payment$JaxbAccessorF_cvv
    Loaded com.foobar.service.order.Payment$JaxbAccessorF_authCode
    Loaded com.foobar.service.order.Item$JaxbAccessorF_productID
    Loaded com.foobar.service.order.Item$JaxbAccessorF_giftWrap
    Loaded com.foobar.service.order.Item$JaxbAccessorF_giftWrapCharge
    Loaded com.foobar.service.order.Item$JaxbAccessorF_giftCertificateEmail
    Loaded com.foobar.service.order.Order$JaxbAccessorF_shippingMethod
    Loaded com.foobar.service.order.ShippingInfo$JaxbAccessorF_address2
    Loaded com.foobar.service.order.ShippingInfo$JaxbAccessorF_city
    Loaded com.foobar.service.order.ShippingInfo$JaxbAccessorF_phone
    Loaded com.foobar.service.order.ShippingInfo$JaxbAccessorF_email
    Loaded com.foobar.service.order.BillingInfo$JaxbAccessorF_fullName
Checked where that class was being instantiated and found in a method it was instantiated every time the method was alled.
private Object transformRequest(final Object oRequest) {
        log.debug("Start private Object transformRequest(Object oRequest)");

        StringWriter sw = new StringWriter();
        ISvcContainer srvRequest = (ISvcContainer) oRequest;
        IOrder myOrder = (IOrder) srvRequest.getSvcField(IESBService.INPUTKEY);
        if(myOrder!= null) {
            log.debug("myOrder:" + myOrder.getPk());
            JAXBContext jaxbContext;
            try {
                jaxbContext = JAXBContext.newInstance(jaxbPackage);
Moved the instantiation to injection.
private String jaxbPackage;
    private JAXBContext jaxbContext;
    public void setJaxbPackage(String jaxbPackage) throws JAXBException {
        this.jaxbPackage = jaxbPackage;
        jaxbContext = JAXBContext.newInstance(jaxbPackage);
    }
Rinse and repeat.
PROCESS 2
If the above process doesn't work and/or is pointing to areas where-in the leak isn't obvious you can also try this method:
Take a heap dump snapshot while keeping the unreachable objects.  Bring this up in the MAT (memory analyzer toolkit), again keeping the unreachable objects.  Then do a search for the suspect packages and look for the GC Roots of these objects which should point to the classes/objects causing the problems.
This process was used where-in the following issues were found to be the root cause:
The problem is that a call to "new" for the generated objects which extended the javax.xml.ws.Service ultimately calls the "Service" object itself, which in turn utilizes a javax.xml.spi.Provider.provider() method which ends up loading a new class.  This results in the class loader leak.  The change is to ensure that each of the *Service classes within the mycompany packages which were calling the generated ones were doing so as a singleton.  
I was able to pinpoint this by bringing up the MAT (memory analyzer toolkit) and looking for the GC Roots to the com.mycompany.foo packages.  Diving in here, then viewing source for javax.xml.ws packages turned up the issue.
The secondary issue was in a custom LOGGER that was created to try and log the SOAP calls.  This logger was re-initializing, and thereby reloading, without them ever being unloaded and ejected, the classes each time.

No comments:

Post a Comment