Thursday, December 6, 2012

Java Garbage Collector magic in action (or how to improve your java code using jconsole and jmap)

In my Java experience it has been somewhat unobvious how to jump from monitoring GC and fancy memory graphs with tools like jconsole to actually improving your code.

The ingredient I was missing apparently before was jmap that is part of JDK.

What the tool does is that it allows you to attach to a live java process by process id (pid) and output the histogram of its objects. Here is how it works:


jmap -histo 22170 > histo_22170.log

In the example, 22170 is the java process pid and command line option -histo makes jmap to output a histogram of objects. One nice thing about jmap is that it allows you build an object histogram on JVM OutOfMemory crash (see some details here).

The first lines of the histo_22170.log look like this, before some bug fixing has been done to the code (more on this in a moment):

 num     #instances         #bytes  class name
----------------------------------------------
   1:      88210219     2943436216  [B
   2:       5198407      455421864  [[B
   3:       5162015      123888360  com.mysql.jdbc.ByteArrayRow
   4:       2005702       95264296  [C
   5:       2006883       64220256  java.lang.String
   6:         37819       53525280  [I
   7:        309332       44543808  com.mysql.jdbc.Field
   8:        923280       36931200  java.util.TreeMap$Entry
   9:         18744       25864528  [Ljava.lang.Object;
  10:        471843       15098976  java.util.HashMap$Entry
  11:         36577        5195248  [Ljava.util.HashMap$Entry;
  12:         18196        4512608  com.mysql.jdbc.JDBC4PreparedStatement
  13:         18196        3202496  com.mysql.jdbc.JDBC4ResultSet
  14:         54308        2606784  java.util.TreeMap
  15:         12809        1903312  
  16:         36571        1755408  java.util.HashMap
  17:         12809        1750136  
  19:         18196        1164544  com.mysql.jdbc.PreparedStatement$ParseInfo

I have marked the relevant parts of the histogram with the bold font. The java process was doing some heavy-duty task for thousands of files and talking to the MySQL DB in a loop to load some meta-information for each of the file. The process was given 4GB max heap size and was not properly finishing, producing OutOfMemory error that in turn crashed the JVM.

The code snippet that was producing this looked like this:

PreparedStatement sqlStatement = sqlConnection.prepareStatement(
                          "SELECT * FROM SOME_TBL WHERE SOME_ID=?");
for(int i = 0; i < some_number_less_than_100; i++) {
    sqlStatement.setString(1, companyIds.get(i));
    ResultSet sqlResult = sqlStatement.executeQuery();
    if (sqlResult != null) {
     while (sqlResult.next()) {
        // do some processing of the query results here
     }
    }
}

Intuitively by now you should feel that something is wrong with the code around the JDBC object management.

Let's have a look on the bolded parts from the top of the object histogram. Apparently, the trending JDBC related objects are com.mysql.jdbc.Field with 309332 instances, com.mysql.jdbc.JDBC4PreparedStatement with 18196 instances and com.mysql.jdbc.JDBC4ResultSet with 18196 instances. Two latter objects have exactly same number of instances and that is reflected in our code, where both objects are re-created in a loop. The visual monitoring tool jconsole was showing constant RAM usage growth and Eden Heap Space being saturated with lots of young objects, while the Survivor Heap Space was not trending at all.

What's missing is releasing the JDBC resources, by calling close() methods on both PreparedStatement and ResultSet.

So let's correct the code:

PreparedStatement sqlStatement = sqlConnection.prepareStatement(
                           "SELECT * FROM SOME_TBL WHERE SOME_ID=?");
for(int i = 0; i < some_number_less_than_100; i++) {
    sqlStatement.setString(1, companyIds.get(i));
    ResultSet sqlResult = sqlStatement.executeQuery();
    if (sqlResult != null) {
     while (sqlResult.next()) {
        // do some processing of query results here
     }
     // missing lines added
     sqlResult.close();
}
sqlStatement.close();

After the two missing statements have been added (sqlResult.close() and sqlStatement.close()), the DB resources started to release properly and the original process began to work properly, without big spikes in RAM usage. The JDBC related objects have also disappeared from the top of the histogram:

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1301417       66169256  [C
   2:       1333656       42676992  java.lang.String
   3:        158410       29981072  [I
   4:        382702       12246464  java.util.HashMap$Entry
   5:        116080        5668216  [B
   6:        230584        5534016  java.lang.StringBuffer
   7:         56760        3632640  java.util.regex.Matcher
   8:         18320        2620552 
   9:         18320        2501360 
  10:           588        2187960  [Ljava.util.HashMap$Entry;
  11:          1460        1733744 
  12:         33570        1523672 
  13:         19495        1247680  java.util.regex.Pattern
  14:         19729        1201136  [Ljava.lang.Object;
  15:          1460        1130688 
  16:         19477        1090712  [Ljava.util.regex.Pattern$GroupHead;
  17:          1312        1080992 
  18:         19096         614976  [Ljava.lang.String;
  19:         18642         596544  java.util.RandomAccessSubList
  20:         18642         596544  java.util.AbstractList$ListItr

Now the process is happily completing with reasonable RAM usage:


Click the image to make it bigger
The diagram shows that Eden Heap Space became much more free of young objects and the Survivor Heap Space gets utilized more. See here, if you want more details on various pools of Heap and Non-Heap memory.

Interestingly enough, this bug was hiding for months in the code base and only manifested itself once more data had to be processed. This made the process to run longer and thus reach and overflow the allocated RAM bounds.

This trivial example shows the importance of monitoring your heavy (and not so) java processes.

Happy monitoring!