Identifying memory leaks using Eclipse MAT - Part 2

As I wrote in Part 1, we identified that there was some sort of memory leak happening within our Java JEE application – so the next steps were to obtain a Heap Dump and run it through Eclipse MAT.

So what is a Heap Dump? From the Eclipse docs

A heap dump is a snapshot of the memory of a Java process at a certain point of time. There are different formats for persisting this data, and depending on the format it may contain different pieces of information, but in general the snapshot contains information about the java objects and classes in the heap at the moment the snapshot was triggered.

The Memory Analyzer is able to work with HPROF binary heap dumps, IBM system dumps (after preprocessing them), and IBM portable heap dumps (PHD) from a variety of platforms.

Typical information which can be found in heap dumps (once more - depending on the heap dump type) is:

• All Objects

Class, fields, primitive values and references

• All Classes

Classloader, name, super class, static fields

• Garbage Collection Roots

Objects defined to be reachable by the JVM

• Thread Stacks and Local Variables

How do we get a heap dump into a .hprof file?

Set the following flags to the java process

·        -XX:+HeapDumpOnOutOfMemoryError writes heap dump on OutOfMemoryError

·        -XX:+HeapDumpOnCtrlBreak writes heap dump together with thread dump on CTRL+BREAK

Or you can fire one via tools jmap or jconsole

·        Sun JMap: <jdkhome>/bin/jmap  -dump:format=b,file=HeapDumpFilename.hprof

 

Our idea was to take multiple heap dumps every 2 hours or so and observe the objects in the heap. As with a thread dump, a heap dump is a static view of the live objects in the heap at that time – so it’s not possible to make a definitive judgment on just viewing one heap dump – hence space it out over some time and observe if the same objects (sometimes these have the same memory address location) are growing and causing a possible leak.

Also remember – at the point of taking a heap dump, Java runs a full GC, so you are left with the live objects in the heap.

We took the first heap dumps every 2 hours, but nothing much was happening for the first 12 hours or so.

Once you have the hprof with you, and have installed Eclipse Memory Analyzer Tool (MAT) just open the hprof in Eclipse and wait for it to do it’s thing.

The page will open with an Overview.

This lists important stuff like the Size of the heap – so in our case, though we have a 2 GB heap the retained size after GC is 473.1 MB.

The graph of “Biggest Objects by Retained Size” will give you immediate clues and this is also reflected in tabular format in the “Dominator Tree” report.



Overview

But the best thing about MAT is the Leak Suspects report which points out clearly potential memory leaks.

 

 

 

So in our hprof, 55% of the heap was being retained by one instance of weblogic.xml.query.xdbc.Context i.e. if this object was reclaimed by GC, we could get back 273 MB of memory. This object was residing at memory location weblogic.xml.query.xdbc.Context @ 0xb2477930

The important thing to see in this view is the Retained Heap

In Memory Analyzer the term shallow size means the size of an object itself, without counting and accumulating the size of other objects referenced from it.

The retained heap is the total objects and memory which this object is holding onto.

 

 

We took the next snapshot after 2 hours of the first heap dump and it showed the same instance of weblogic.xml.query.Context@0x7c1642f8 had now grown to 301.6 MB with the total heap now at 524.7 MB

 

Our last snapshot in confirming our problem was after a further 2 hours, so a total of 4 hours since the first heap dump showed this object.

The heap had now grown to 616.5 MB with 54% of it occupied by the same object

 

 

So next we now found out from MAT what was causing the leak. We next had to analyze how this class weblogic.xml.query.xdbc.Context  was being used in the app and how we could prevent the leak. I will post that in Part 3.

Weblogic JMS Performance Tuning Tips

Here are a couple of real-life tips on tuning JMS performance.

Problem:
The creates and sends JMS messages on an outgoing queue for consumption by another application.

It was observed that when the consuming application was offline for a period of time the number of messages that could be retained on the queue before the JVM heap was filled up was quite low. This was tested to be roughly 7000 messages, after which OutOfMemory exceptions begin to occur. Given that the consuming application could realistically be offline for a period, hence the use of an asynchronous queue, we needed to increase the number of messages that could realistically be stored in the queue.

The exception we get is shown below:

Start server side stack trace:
java.lang.OutOfMemoryError:

Start server side stack trace:
java.lang.OutOfMemoryError
        <<no stack trace available>>
End  server side stack trace
        at weblogic.rmi.internal.BasicOutboundRequest.sendReceive(BasicOutboundRequest.java:109)
       at weblogic.rmi.internal.BasicRemoteRef.invoke(BasicRemoteRef.java:127)
       at weblogic.jms.dispatcher.DispatcherImpl_WLStub.dispatchSyncFuture(Unknown Source)
       at weblogic.jms.dispatcher.DispatcherWrapperState.dispatchSync(DispatcherWrapperState.java:286)
       at weblogic.jms.client.JMSSession.createProducer(JMSSession.java:1484)
       at weblogic.jms.client.JMSSession.createSender(JMSSession.java:1335)
...

The GC logs also show frequent Full GCs before the server goes out of memory.


Solution Steps:

1. Enabling JMS Paging

Paging had not been enabled for the queue. Despite this queue being persistent, this meant that every message was stored in the JVM memory heap in its entirety. Enabling message paging for this queue means that only the headers for paged messages are kept in memory, significantly reducing the amount heap utilized.

As the messages were being persisted via a JDBCStore to a database, this functioned as a paging store as well, however a FileStore must still be specified as the paging store for the JMS Server, or the JMS Server will not deploy at WLS server start time. This would be due to the need to cater for any non-persistent destinations when paging is enabled. If non-persistent messages are not paged, the size of this FileStore will be negligible. Paged messages still occupy some space on the memory heap as the message headers are still kept in memory.

On enabling paging for the specific queue, the test could cater for roughly 15000 messages before OutOfMemory exceptions occurred. The point at which paging began was set deliberately low to 100. Recovering from the page store does incur a certain performance cost, so in Production this was set to a more reasonable number based on the peak number of messages expected in the queue under normal conditions.

Despite the gain in number of messages that could be catered for, the heap utilisation graphs were very similar to those before paging was enabled. This showed no minor GCs, only full GCs at fairly frequent intervals.


2. JVM Settings and Garbage Collection Tuning

The untuned JVM heap size was 512Mb. This value could be increased, but test results after tuning the JVM settings indicate that this was probably more than adequate.

Examining the current JVM settings uncovered some settings that needed to be changed.

The most significant issue with the JVM settings was the NewSize value. This was set very high to 384Mb out of the total heap of 512 Mb.
A reasonable New Generation area would normally be 20-25% of the total heap size and setting it larger than the Tenured Generation area is guaranteed to cause unhealthy GC operations. In addition, it is good practice to use NewRatio rather than NewSize to avoid fixing an absolute size. A NewRatio of 3 (1:3, i.e. 25% of heap) or 4 is considered the most appropriate for WebLogic Server applications. NewSize was therefore dropped and a NewRatio was set to 4 (20% of total heap).

The SurvivorRatio value was set to a reasonable value of 3.
TargetSurvivorRatio, however, was unset meaning that the default of 50 applies. 80 would probably be a better setting, meaning that the switch between survivor spaces in the JVM heap would occur at 80% rather than 50%. The performance improvement from this should be noticeable in the frequency of minor GC, though not dramatic.

The PermSize values were high, with PermSize and MaxPermSize both set to 384Mb. These were reduced to 64Mb and 128Mb respectively, which should be more than adequate. Though these changes are unlikely to improve performance, having the PermSize set to high will needlessly consume memory.

The effect of setting a good NewRatio value was dramatic. Many minor GCs were the rule, with infrequent full GCs. 60,000 messages were added to the queue before the heap was approaching full. We ran an overnight, and somewhere between 60,000 and 70,000 messages the OutOfMemory exceptions occurred.

Scaling this up to the Production environment which has 1Gb Heap, shows that the server could easily cater for the expected load.

JVM Tuning from the Trenches

This article is a follow-up to http://jojovedder.blogspot.com/2009/06/slow-weblogic-part-6-jvm-heap-analysis.html. Please read that one first for the basics on JVM heap, parameters and flags.

Also remember these tips have worked for the server settings and issues faced below, but blindly using these on your server will not produce the same results. You have to measure and then tune after measuring.

Problem:
Platform running Weblogic 8.1 on Sun V880 servers. Total RAM of 32 Gb on the machine.
2 Gb assigned to the managed server JVM heap. JDK 1.4

Initial settings:

-XX:+AggressiveHeap -Xms2048m -Xmx2048m  -XX:SurvivorRatio=32 -XX:MaxPermSize=128m 

But still there are 20 Full GCs per hour in peak times, before the server crashes.


Analysis

1. It was decided to reduce the SurvivorRatio to 4 and restart with some more flags.

The size of ONE Survivor Space is calculated as

SurvivorSpace = NewSize / (SurvivorRatio + 2)

Keeping SurvivorRatio as 32 means the Survivor spaces are too small for promoting stuff from Eden. Hence we reduce this to 4 which allows for larger Survivor spaces.

2. As per Sun Bug ID: 6218833, setting AggressiveHeap set before Heapsize (Xmx and Xms) can confuse the JVM. Revert the order to have -Xms and -Xmx to come before -XX:+AggressiveHeap or not use it

3. The application has 180+ EJBs with pools of beans. Hence set the -Dsun.rmi.dgc.client.gcInterval=3600000 (1 hour) instead of the default 60000 (1 min). More on this here: http://docs.sun.com/source/817-2180-10/pt_chap5.html

4. The site is restarted once a week at 4:30AM. The patterns stays normal for 2 days – and then degrades into full GC.

5. The Old space is pretty much full – at every minor collection – the Old space must be cleared up for promotion from Young to Old to take place.

6. Permanent space is pretty much full – keeps loading classes and classes ( could that be a problem – the difference between the number of JSP’s per Release?)
Hence we increased the PermSpace from 128M to 256M

7. Ensure we are running the server JVM by using the -server flag

8. Use OptimizeIt or similar profiling tool to see the memory usage and find code bottlenecks.


The settings now were

-server -Xms2048m -Xmx2048m  -XX:MaxNewSize=512m -XX:NewSize=512m -XX:SurvivorRatio=4 -XX:MaxPermSize=256m -Xincgc -XX:+DisableExplicitGC -XX:+AggressiveHeap -XX:-OmitStackTraceInFastThrow

This reduced the Full GCs to one a day.

Error Logs

At the time of the server going out of memory prior to a crash, the logs are filled with repeated errors (up to 100 repetitions) of this sort

java.lang.NullPointerException
 <<no stack trace available>>

Adding the -XX:-OmitStackTraceInFastThrow flag resolves this problem, the root cause of the NPE it self has to be tracked down but we do not have any longer the issue of huge recursive exception strings.

We could now see the stack trace as

java.lang.NullPointerException
 at java.util.StringTokenizer.(StringTokenizer.java:117)
 at java.util.StringTokenizer.(StringTokenizer.java:133)
 at jsp_servlet._framework._security.__login._jspService(login.jsp:294)
 at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
 at weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run(ServletStubImpl.java:1075)

This seems to be a Sun bug described here.

Simultaneous Solaris T2000 core dumps on local zones

Issue:

Our applications run on Sun T2000 servers which are configured with 4 or 5 Local zones on each Global Zone.

17th November 05:00 there was an issue on one Global Zone which caused 5 separate and simultaneous core dumps to get created on the server. One core in each Local zone.




Impact:
The 5 processes which crashed on each Local zone were

LZ 15 – core created by the wlshell java process. Low impact
LZ 27 – one core created by wlshell java processes. Low impact.
LZ 25 – core created by HM server java process. Was manually restarted today. Medium impact
LZ 26 – core created by PA server java process. This was automatically restarted by the HM. High impact.
LZ 37 – core created by HM server java process. Was manually restarted today. Medium impact




All 5 crashes above were in Library=/platform/sun4v/lib/libc_psr.so.1

Each core exits with a hs_err_.log file - which contains the foll details

An unexpected exception has been detected in native code outside the VM.
Unexpected Signal : 10 occurred at PC=0xFF2709F0
Function=_memset+0x70
Library=/platform/sun4v/lib/libc_psr.so.1

Current Java thread:
at java.lang.Thread.start(Native Method)
- locked <0xf1f3a378> (a java.util.logging.LogManager$Cleaner)
at java.lang.Shutdown.runHooks(Shutdown.java:126)
at java.lang.Shutdown.sequence(Shutdown.java:165)
at java.lang.Shutdown.exit(Shutdown.java:210)
- locked <0xf5998498> (a java.lang.Class)
at java.lang.Runtime.exit(Runtime.java:90)
at java.lang.System.exit(System.java:715)
at ConsoleScriptRunner.main(ConsoleScriptRunner.java:64)

Investigations


1. Seems to be running out of swap at the time of the crash. Memory: 31.9G real, 4.0G free, 37.7G swap in use, 2.4G swap free
Update: added 50 G swap on 19/11 - Memory: 31.9G real, 3.4G free, 38.0G swap in use, 52.8G swap free


2. Application Support is identifying what the wlshell process does – it seems to be a Weblogic server monitoring script running every 10 minutes under cron.


3. Library=/platform/sun4v/lib/libc_psr.so.1 Are there any known issues with this library on solaris 10 or T2000? Support to query SUN


The libc_psr libraries implement platform-specific, optimized versions of block copy and move routines from libc, such as memcpy(). On UltraSPARC machines, these routines are coded in assembler, and use block load and store ASI's, prefetch, and other tricks for better performance.


Root Cause

Sun identified that the issue was related to known bugs in JDK 142_03 and running an old version of libc_psr.so

The ( a) type error as seen in hs_err_pid6216_18111030.log the error was a know java bug with the j2sdk1.4.2_03 and the bug is identified as :


Bug ID: 4927116 fixed in 1.4.2_04 Synopsis Regression: 1.4.2 JVM core dumps in ClassLoader.defineClass0()

Actions

1. Immediate action is to upgrade to JDK 142_18

2. Also identified that all 5 core dumps were created by sh scripts running under crontab. Further analysis showed that there were cron jobs running every 15 mins on each of the zones - and this puts a load on system resources especially around memory consumption in the JVM and sufficient unhanded exceptions between the java virtual machine and the operating system could cause the then dead locked JVM to terminate .


Thus the 2nd resolution was to offset the start time of each cron job - to try and ensure no two jobs run on the same Global Zone at the same time.


Old Timings:

0,15,30,45 * * * * /export/home/Handlers.sh > /tmp/Handcheck
0,15,30,45 * * * * /export/home/Average_response_time.sh > /tmp/Avgcheck
0,15,30,45 * * * * /export/home/Msg_In_and_Out_count.sh > /tmp/Mescheck
0 0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23 * * * /log/zipper.sh

New Timings:

1,16,31,46 * * * * /export/home/Handlers.sh > /tmp/Handcheck
2,17,32,47 * * * * /export/home/Average_response_time.sh > /tmp/Avgcheck
3,18,33,48 * * * * /export/home/Msg_In_and_Out_count.sh > /tmp/Mescheck
4 0,2,4,6,8,10,12,14,16,18,20,22 * * * /log/zipper.sh

Also knocking off unnecessary cron jobs from the box to reduce the load.