How to find Java Memory Leaks - Part 2

In the previous post I looked at how to monitor your application in test or production to observe its heap behaviour and understand whether or not you have a memory leak. In this post I will start to look at the next step - how to gather data to help to trace the root cause of your leak.

In some simple cases it is possible to use inspection of the source code, a debugger or trace statements to figure out what is going wrong by spotting where the developer has made a mistake. If this works for you, then that's great. I want to focus on the more complex situations where you are dealing with lots of code and lots of heap objects that may not be yours and you can't just go straight to a piece of Java and see what the problem is.

To understand a memory leak we usually need to use tools which are very different from those used to diagnose other issues. For most issues we want to understand the dynamic behaviour of our code - the steps that it performs, which paths it takes, how long it takes, where exceptions are thrown and so on. For memory leaks we need to start with something completely different - namely one or more snapshots of the heap at points in time which can give an insight into the way it is being used up. Only once we have this picture can we start to work back to the code to understand why the heap is being used up.

Before going any further, a small warning - most of the techniques from here on are not well suited to production environments. They can hang the JVM for anything between a few seconds and a few minutes and write large files to disk. You really need to reproduce your issue in a test environment and use these tools there. In a crisis, you may be allowed to use them in production if your app is already under severe heap stress and is about to be killed or restarted anyway.

The simplest type of snapshot is a heap 'histogram'. This gives you a quick summary (by class) of which objects are consuming the most space in the heap including how many bytes they are using and how many instances are in the heap.

There are a couple of ways to get a histogram. The simplest is jmap - a tool included in some JDK distributions from Java 1.5 onwards. Alternatively, you can get a histogram using a JVM startup argument -XX:-PrintClassHistogram and sending your app a Ctrl-Break (Windows) or kill -3 (Unix) signal. This JVM option is also settable via JMX if your JVM is recent enough.

Here is an example (from a test app that deliberately leaks memory)...

andy@belstone:~> jmap -histo 2937
Attaching to process ID 2937, please wait...
Debugger attached successfully.
Client compiler detected.
JVM version is 1.5.0_09-b03
Iterating over heap. This may take a while...
Object Histogram:

Size Count Class description
-------------------------------------------------------
65419568 319406 char[]
7472856 311369 java.lang.String
1966080 61440 MemStress
596000 205 java.lang.Object[]
64160 4010 java.lang.Long
34248 13 byte[]
32112 2007 java.lang.StringBuffer
10336 34 * ObjArrayKlassKlass
4512 47 java.lang.Class
4360 29 int[]
(snip)
8 1 java.lang.reflect.ReflectAccess
8 1 java.util.Collections$ReverseComparator
8 1 java.util.jar.JavaUtilJarAccessImpl
8 1 java.lang.System$2
Heap traversal took 42.243 seconds.
andy@belstone:~>

There are a few things to note here:-

• Using this tool will hang the JVM until it has finished the histogram dump - in this case for 42 seconds. Don't try this if you can't afford to hang your JVM.
• The objects highest in the list are java Strings and their associated character arrays. This is very common. You may also see other built in types (e.g. collections) near the top of the list.
• What you should usually look for are the classes which appear highest in the list over which you actually have some direct control. This should give you the best clue about what types of object are involved in your memory leak.

In the (rather contrived) example above, the class 'MemStress' looks like it could be the real consumer of the heap space and indeed it is. Even though we've found it, most of the space it is using is being used indirectly - in this case by the Strings it uses to hold its instance variables. We were fortunate that MemStress objects on their own are big enough to push the class high enough up the list to be noticed. In some cases you may not be so lucky - instances of the main culprit may be quite small and it may therefore be hiding lower down the list. Try importing the list into a spreadsheet and sorting by instance count to see if that offers any additional clues.

It's usually best to have several heap histograms from the same run of your app at different points in time. Comparing these will give you a much better picture of how your memory leak is building up over time. Try to arrange to trigger them so that your app is in a similar state (usually idle) for each dump - then you will be comparing 'like for like'.

A heap histogram may be all you need to figure out what's going wrong, in which case you can don't need to worry about the next step.

What a histogram can't tell you is why each object is staying in the heap. This happens because at least one other object is still holding a reference to it. A full heap dump has the information needed to trace these references and also look in detail at the values of individual attributes in every object on the heap. It's also a big step up in size and complexity from a heap histogram. I'll look at how to take and analyse a full heap dump in the next installment.

How to find Java Memory Leaks - Part 1

Java heap consumption and memory leak diagnosis is something that (judging by other posts around the net) is often misunderstood - I've lost count of the number of searches that have turned up advice to simply increase the heap size and hope the problem goes away.

Let's address this one question straight away - if you really have a memory leak, increasing the heap size will at best only delay the appearance of an OutOfMemoryError. If your issue is just a temporary spell of high demand for heap memory then a bigger heap may help. If you take it too far you may see much worse performance because of swapping or even crash your JVM.

So what should you do? In essence, I would recommend three steps:-

1. Monitor your application in test and/or production to get an understanding of its heap behavior
2. If you really do have a problem, you need to gather data to help to track down the cause.
3. Finally having got the data, you need to figure out what it means - what is causing your problem and how to fix it.

Sadly these steps are not always easy to do - particularly step 3.

I'll be talking about the Sun JVM from here on, although many of the same principles and sometimes tools apply to other JVM implementations.

First let's look at monitoring...

To get a clear picture, you really need to look in detail at the heap stats from your JVM, but I quite often find that these are not available when I'm first asked to look at a problem, so what can we tell without this?

Clearly if you see this in your application logs then there is a problem...

java.lang.OutOfMemoryError: Java heap space

The usual response if you have real users is to restart the application straight away. You should then continue to monitor because you're probably going to need to know more before you get to the end of the diagnosis.

I often start by looking at CPU consumption using top, vmstat or whatever tools are available. What I'm looking for is periods where the Java app is using close to 100% of a single CPU. While it's not conclusive proof (being stuck in a loop could cause the same effect), this often means that the app is spending a lot of time doing full garbage collections - the most commonly used garbage collectors are single threaded and therefore tend to use 100% of a CPU.

Monitoring memory usage from the operating system is not very informative - Java will typically grow the heap to the maximum size long before there is a problem. If you have oversized your heap compared to physical memory you will probably see heavy swapping activity, but that's a different issue.

Some applications and app servers will make calls to java.lang.Runtime.freeMemory(). While this may be better than nothing, it's fairly uninformative and provides very little info about which generations have free space, how much time is being spent garbage collecting and so on.

The JVM can provide much more detailed info about what is going on. The JVM itself provides two main ways to get hold of this:-

1. JVM Startup arguments to write information to log files. Here are some suggestions, but check the docs for your specific JVM version (or try here) because the available options vary:-

-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintTenuringDistribution

You may also want to add -Xloggc:myapp-gc.log to send your GC info to a dedicated log file

You can then analyse the log files to produce a graph using a tool such as gcviewer. This approach gives you detailed information about every GC run but be careful to check that you have enough disk space - these options can produce a lot of data. Typically you will also need to restart your app to enable these options, although they are also controllable via JMX for more recent JVM versions.

2. JDK tools - jvmstat in Java 1.4 and jstat in Java 1.5 and higher. These are tools that you run from the command line. They connect to your Java app via one of the JVM debugging APIs and will then report on heap and GC stats according to the options you specify. I usually use jstat -gcutil -t 60s which produces a line of output once per minute showing the percentage utilisation of each heap space, plus the number of young and full GC events and the cumulative GC times. You can then open the resulting text file in Excel for analysis. Note that jstat is capable of monitoring Java 1.4 VMs, which is handy if you have multiple versions. Alternatively (if your environment allows) you can try visualgc for an instant GUI view but I prefer using jstat to collect logs for offline analysis.

There are other commercial tools (e.g. Wily Introscope) which can provide the same data as the JDK tools. They may provide better visualisation, historical reporting and perhaps proactive alerting but I don't intend to cover them in detail here because most readers probably don't have them.

So what should you look for to know whether you have a problem?

• OutOfMemoryErrors in your application logs - clearly you have a problem if you are getting these.
• A persistent upwards trend in the Old Generation usage after each full garbage collection.
• Heavy GC activity. What 'heavy' means is rather dependant on your application. A rule of thumb for a non-interactive app might be 15 seconds during each minute - which means that your app only has 75% of its time left to do useful work. You might choose a lower figure or look at the duration of individual full GC runs, especially if your app has real users waiting for it.

Finally, some pictures. Here is a graph showing jstat data from an app on WebLogic 9.2 with a heap memory leak - you can see that the Old Generation usage is climbing, even after garbage collection.

Here is another graph from the same app. The original leak has been fixed and there is now no evidence of a cumulative memory leak, but there are some intermittent spikes in heap usage. If the spike is severe enough it can still cause an error. Tracking this problem down will need some knowledge about what unusual types of system activity are occurring at the time of the spike.


Here is a graph drawn by gcviewer after using JVM startup arguments to produce a log file. The graph is quite 'busy' and includes a lot of extra info - for example this app's arguments allow the heap to grow as more is needed. The graph shows the growth in overall heap size as well as the growth in consumption. This info is available using jstat too, but if you really need it all then using gcviewer will probably be more convenient.

In the next post I'll look at how to gather data to help trace the cause of your memory leak.

Java Heaps and Virtual Memory - Part 2

The story so far... in my earlier post I described a memory stress test that demonstrated the soundness of the advice to keep your Java heap size smaller than your physical memory.

I also wanted to check on the very limited explanations that I'd found and get a better understanding of what was going on. In particular, I wanted to know how Java (i.e. the Sun JVM) allocates heap memory and whether it adopts any strategies to avoid swap thrashing.

I did some further digging using the various things under the /proc file system and the JDK source code to find out.

The first surprise was in /proc/meminfo - the only counter that was going up significantly during the test was 'Mapped' - i.e. memory mapped files. I was expected this approach to be used for reading in .jar files and native libraries (and it was), but I wasn't expecting this for the heap. Digging into the source code explains why - The JDK uses the mmap system call to request more heap memory from the O/S.

I also took several snapshots of /proc/PID/smaps to see exactly what memory regions were being used in the processes address space. What this showed was:-

1. There was a memory region (in my case starting from 0x51840000) that was clearly growing as the app allocated more and more heap. During the early part of the app's execution this would show up with a resident size 7Mb less than its overall size and with all of the resident pages showing up as being dirty.
   
2. Once memory started to become scarce, many of the other memory regions start to show a reduction in their resident sizes and their shared sizes.
3. Once swap thrashing was happening, the memory region which had been growing still had a 6-7Mb difference between the resident size and the allocated size. The big difference, however was that 15Mb of the space was now showing up as 'Private_Clean'.

So what does it all mean? Here's what I think is happening...

1. During the early stages of execution the app is getting as much memory as it asks for but Linux delays giving it real physical memory until the specific pages are really accessed. This explains why the resident size is less than the allocated size - Java has probably extended the heap but hasn't yet accessed all of the allocated space.
2. Memory is getting scarce, so Linux starts to reclaim pages that have the smallest impact. In the first instance it is hunting around for less critical pages (e.g. pages of jar files or libraries that haven't been used recently) that it can reclaim.
3. This behaviour surprised me a little - I was expecting the resident size of the heap to have reduced, but this doesn't seem to have happened. What we can see is that part of the heap is now 'clean' - this tells us that Linux has indeed flushed part of the heap out to the swap file. The fact that the resident size has not reduced significantly tells us that we aren't getting much benefit - basically I think that the swapper is trying to swap pages out but the garbage collector is pulling them all back in again.
   

Finally I went back to the JDK sources again to see whether these would help me to understand what was going on. What I really wanted to understand was where the per-object data used by the garbage collector resides. The answer appears to be that it resides at the beginning of the memory block allocated to the object itself. The implication of this is that with 'normal' sized objects, the garbage collector run will need to access a few fields at the start of every single object on the heap, thus generating read and write accesses to practically every page contained in the heap.

So it would seem to me that the design choices in terms of the in-memory layout of objects and their garbage collector data mean that the garbage collectors really do conflict with the swapper once memory becomes tight. Based on the simple test that I did earlier, this happens both suddenly and with a severe impact.

In real life situations there may be several other Java and non-Java apps running on the same machine. I think this has a couple of implications:-

1. The requirements of other apps may mean that memory becomes scarce much sooner - i.e. well before your Java heap size reaches the amount of physical memory.
   
2. The swapper is not redundant - there may be plenty of 'low risk' pages belonging to other apps (or JAR mappings used only at startup time) that can be swapped out before the system gets to the point of swap thrashing.

Java Heaps and Virtual Memory - Part 1

Virtual memory has been around for a long time - Wikipedia reckons that it was first introduced in the early 1960s and it's still with us today. When we start using Java for large scale applications, however, it seems that virtual memory is perhaps not such a good thing. Several sources around the Internet recommend sizing the Java heap so that it fits within physical memory. The reason given is that the Java garbage collector likes to visit every page, so if some pages have been swapped out the GC will take a long time to run.

This question has cropped up on several occasions in my current project. While I have no reason to disagree with the advice on heap sizing, I was a little uncomfortable that I hadn't seen much real evidence to back it up or indication of how bad things would be once the limit was reached, so I decided to find out for myself.

The first thing I tried was creating a simple Java class to stress the heap. This class will progressively populate an ArrayList with a large number of Java objects each owning five 80 byte random strings. It can also be asked to 'churn' the objects by selecting and replacing groups of them, thus making the old ones eligible for garbage collection. I ran this on a small Linux box and watched what happened using 'top' and 'vmstat' ...

What I found was this...

1. While there was plenty of free memory, the resident size of the process grew.
2. Once free memory became short, the shared size started to shrink
3. Very soon after that, the swap file usage started to grow
4. If the 'churn' feature of the stress test was enabled, the system quickly got into heavy swap thrashing and the stress test ground to a halt.
5. With no churn (probably not realistic for most real apps), the app could get a little further, but not much and would still get into swap thrashing.

My original intention was to capture some numbers and draw a graph or two to illustrate what happens. In practice what I found was that the results were rather variable, even on the same machine. In every case though there was a point soon after swapping started where the test tipped dramatically into swap thrashing and was unable to make any further progress.

I drew two conclusions from my simple test:-

1. The advice to keep the Java heap smaller than physical memory is very sound.
2. The degradation in performance if you let your Java heap grow bigger than physical memory is both sudden and severe.

I also wanted to check on the very limited explanations that I'd found and get a better understanding of what was going on. In particular, I wanted to know how Java (i.e. the Sun JVM) allocates heap memory and whether it adopts any strategies to avoid swap thrashing. I'll save this for a later post.

Groovy for database business logic

My first impressions of Groovy as a way to solve my database-oriented business logic problem are very good.

I started out by re-implementing the stored procedure logic that I'd prototyped as a Groovy class. I got it working and passing the unit test in a couple of hours. My first implementation was fairly horrid, but over the next few hours I figured out some more of the Groovy idioms and removed some Java style code which made the whole thing more expressive and easier to follow.

One thing which took some figuring out was date handling and date arithmetic. I started out using the java Calendar class, which was somewhat verbose. I then found http://groovy.codehaus.org/JN0545-Dates which explained some useful stuff like the Groovy Duration classes. These made my code much more concise, although I'm not too comfortable about the fact that you can do 'duration + java date', but not the other way round. I can see exactly why it is so (because java.util.Date doesnt have a 'plus' method), but it's rather counter-intuitive.

While it was in the state of being a 'like for like' copy, I also took the opportunity to do a couple of comparisons:-

• lines of code (including blanks and comments) - 66 for Groovy, 87 for the stored procedure - the savings were mainly down to the elimination of variable declarations at the start of the procedure and the much simpler looping syntax with Groovy.
• performance - I was only able to test on my local Windows machine, which is not ideal, but with a sensible amount of data, the Groovy version was taking about 7% longer than the stored procedure version.

Since my code has an inner loop with a complex SQL insert/select statement in it, I thought it worth looking at what Groovy was doing with this. Using the (Eclipse) debugger, I found that it was creating a new PreparedStatement for each iteration of the loop, which I thought may be costing some performance. I tried expanding this operation out to explicitly create a PreparedStatement outside the loop and execute it inside the loop. The result was zero improvement in performance, but some pretty ugly code so I undid this change.

Overall, Groovy looks like it is meeting my requirements as a way to implement complex database business logic, so I'm now about to start on turning my prototype logic into something which can meet the rather more complex requirements of the real thing.

Time to be more Groovy

Following a recommendation from a colleague, I've had good intentions to learn and use more Groovy for quite a while now, but somehow havent quite had a problem that really presents itself as the ideal starting point.

A few months back I took the initial plunge and used Groovy to do a real job. The job probably wasnt the best choice as a first Groovy project - it was basically pulling data from a multi-gigabyte binary file (actually WebLogic JMS storage files), but it needed to be done and I got the job done with Groovy. In the end I probably wished I hadn't done it this way because I couldn't then use the resulting script anywhere else without getting Groovy set up there first and the alternative was shifting the huge files to the machine where the script was working. I don't think I really learned much idiomatic Groovy either.

Today I have a new problem to solve - basically I have some complex pricing calculations to do based on data in a relational database. The calculations need to be done both in scheduled batch mode and 'on the fly' within a J2EE app for 'what-if' style illustrations. They also need to be very pluggable so that entirely different pricing structures can be supported.

Thinking about this problem, what I need is:-

• Must be runnable from a J2EE app
• Must have good DB integration
• Must have automated unit tests
• Must have concise, expressive logic and preferably polymorphism
• Must be easy to debug

The initial prototype (with lots of simplifying assumptions) was done as a stored procedure with DBUnit test cases, which nicely meets the first three requirements, but runs out of steam on the third. I think that continuing with this approach is going to result in something pretty cumbersome as I gradually remove the simplifying assumptions.

Native Java didn't seem too attractive in terms of really tight DB integration - both JDBC and Hibernate fall a long way short of the simplicity with which SQL can be used in a stored procedure.

So I took another look at Groovy - it seems to fit the bill pretty well. I suspect that GSQL will be rather less cumbersome than either raw JDBC or Hibernate, although probably not quite as closely integrated as running SQL inside a stored proc. I was also worried (based on past experience of Jython and Javascript) about debugging, but it seems that this angle is also covered with both JSwat and Eclipse being supported. Hopefully it will also get me into more idiomatic Groovy in the process...

We shall see!

An Accident Waiting to Happen

My client is in the process of rolling out a multi-tier J2EE application which has been in development for a couple of years. A couple of weeks ago, it started to run into mysterious 'hanging' states in production. Many crisis meetings took place, DBAs and app server experts were engaged, actions happened and everybody had a generally stressful time without quite getting to the bottom of the issue.

In a quieter moment, going over emails from the DBAs, thread dumps and source code, I spotted a problem. A Java class was querying Oracle for the next value of a sequence, putting it in an instance variable and then using it later to do an insert or an update. Nothing too scary on the face of it... until you realise that an instance of this class was being held in an instance variable in another class, and that class was a WebLogic web service skeleton.

Now the WebLogic manual is very clear that you must write thread-safe code for your skeleton classes because the server will use a single instance of the skeleton to service all client requests. End result: a single instance of our class is running in multiple threads and the database keys are getting mixed up between threads, resulting in multiple threads trying to lock the same database row and causing the app to hang.

So should we blame the developers of this class?, well maybe, but bear in mind that the class in question is not itself a web service skeleton - it just happens to be used by one. Maybe we should blame the developer of the skeleton?, well that may be closer to the mark, but I have another option - maybe we should blame the developer of the web service framework!

My question is: is this rule reasonable? The expectation nowadays is that developers will quickly be up to speed with new technologies and that businesses will want to take advantage of them quickly. We cant expect development shops to be peopled entirely by seasoned professionals, so surely the burden should fall on the developers of frameworks to implement default behaviours which are safe.

Having hit this issue, I cross-checked what Axis does in the same situation. At first, I couldn't find any definitive statement in the manual on the subject, so I ran a service in the debugger and found that it created lots of instances of my skeleton as calls arrived. I eventually found that the bahaviour is configurable via the 'scope' property in the web service deployment descriptor (WSDD). The default seems to be 'session' - i.e. an instance of the skeleton is created for each client that connects. Not 100% safe, not 100% optimal performance-wise, but probably safe enough for most situations.

My client now needs to either check all web-service related code for thread safety or switch to another web service framework that at least makes this behaviour configurable... and then roll out the change into production and retro-fit the two releases which are still in the pipeline. This is not going to be a painless process.

I will just be thankful that I wasn't around when the framework was chosen or when the code in question was written - would I have spotted this accident before it happened?