Java Memory Profiling using JHat


Problem: How to do memory profiling for a java application

Solution: I have chosen to use jdk inbuilt feature jhat to acheive this.

jhat Utility

The jhat tool provides a convenient means to browse the object topology in a heap snapshot. This tool was introduced in the Java SE 6 release to replace the Heap Analysis Tool (HAT).

The tool parses a heap dump in binary format, for example, a heap dump produced by tomcat or jConsole.  There are couple of ways to produce a dump whenever an outOfMemory Exception happens, which i will brief a little later. Once the dump is available, use jhat to analyze the dump and jhat produces a html that contains the all the classes and object instances count and other useful information.

First step would be to set up generating a dump upon an OOM exception that we will use later to be analyzed by jHat

Option 1 to generate dump file: Use JConsole

Once you start jConsole from command prompt as

c:\> jConsole

1. Select Remote Process

2. Enter hostname:JMXPort (JMX need to be setup for your environment to be able to use jConsole) Find out JMXPort from the tomcat instance

3.  Enter a userid that has edit access and password.

4. Once connected,  Go to the MBeans tab and open:
com.sun.management
HotSpotDiagnostic
Operations
dumpHeap

Fill in ‘testdump.log’ in the ‘String’ inputbox and press ‘dumpHeap’.

Option 2 to generate dump file: Use server settings

Go to your environment and edit tomcatstartup options as

-server -Xms256M -Xmx512M -XX:PermSize=256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/testdump.log -XX:MaxPermSize=256m -Djava.awt.headless=true -Djava.net.preferIPv4Stack=true

Now, we have done our setup to generate a dump file names testdump.log, in one of the above two ways.

Now if at any point during your application, you encounter OOM exception, this log will be generated.

Use jhat tool to visualize the heap

Type jhat command and select a port free to use, otherwise binding exception will occur. To find what port is free, use

netstat -an | grep (port) | grep -i listen

If the port listens, its in use.

jHat itself needs of of heapsize to analyze big dump files, so make sure you set it to 1G or more as available.

C:\Program Files\Java\jdk1.6.0_21\bin>jhat -port 7010 -J-Xmx1G c:\testdump.log
Reading from c:\testdump.log…
java.io.IOException: Map failed
at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:758)
at com.sun.tools.hat.internal.parser.MappedReadBuffer.create(MappedReadB
uffer.java:47)
at com.sun.tools.hat.internal.parser.HprofReader.<init>(HprofReader.java
:145)
at com.sun.tools.hat.internal.parser.Reader.readFile(Reader.java:76)
at com.sun.tools.hat.Main.main(Main.java:143)
Caused by: java.lang.OutOfMemoryError: Map failed
at sun.nio.ch.FileChannelImpl.map0(Native Method)
at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:755)
… 4 more
File mapping failed, will use direct read
Dump file created Thu Jun 09 14:42:10 EDT 2011
Snapshot read, resolving…
Resolving 5203574 objects…

Chasing references, expect 1040 dots……………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
………………………………
Eliminating duplicate references…………………………………………
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
……………………………………………………………………..
…………………………..
Snapshot resolved.
Started HTTP server on port 7010
Server is ready.

Jhat will parse the heap dump and start a web server at port 7000. Connect to Jhat server by pointing your browser to:

http://localhost:7010

And start investigating.

Jhat allows you to see what objects are present in the heap, who has references to those objects, etc.

Look for:

  • Instances, but not _classes_.
  • Instance counts can be seen at: http://localhost:7010/showInstanceCounts/
  • Use “Reference Chains from Rootset” (Exclude weak refs!!!) to see who’s holding the instance.

The above output tells you an HTTP server is started on port 7010 by default. To view this report enter the url http://localhost:7000 or http://your_machine_name:7010 in your web browser.

The default report view contains a list of all the classes. At the bottom of this initial page are the following two key report options:

  Show all members of the rootset
  Show instance counts for all classes

If you select the Show all members of the rootset link, you see a list of the following references because these reference are likely targets for potential memory leaks.

 Java Static References
 Busy Monitor References
 JNI Global References
 JNI Local References
 System Class References

What you look for here are instances in the application that have references to objects that have a risk of not being garbage collected. This can sometimes occur in the case of JNI if memory is allocated for an object, the memory is left to the garbage collector to free up, and the garbage collector does not have the information it needs to do it. In this list of references, you are mainly interested in a large number of references to objects or objects of a large size.

The other key report is the Show instance counts for all classes. This lists the number of calls to a particular method. The String and Character array objects, [S and [C, are always going to be high on this list, but some objects are a bit more intriguing. Why are there 323 instances of java.util.SimpleTimeZone for example?

  5109 instances of class java.lang.String
  5095 instances of class [C
  2210 instances of class java.util.Hashtable$Entry
  968 instances of class java.lang.Class
  407 instances of class [Ljava.lang.String;
  323 instances of class java.util.SimpleTimeZone
  305 instances of class
        sun.java2d.loops.GraphicsPrimitiveProxy
  304 instances of class java.util.HashMap$Entry
  269 instances of class [I
  182 instances of class [Ljava.util.Hashtable$Entry;
  170 instances of class java.util.Hashtable
  138 instances of class java.util.jar.Attributes$Name
  131 instances of class java.util.HashMap
  131 instances of class [Ljava.util.HashMap$Entry;
  130 instances of class [Ljava.lang.Object;
  105 instances of class java.util.jar.Attributes

To get more information on the SimpleTimeZone instances, click on the link (the line beginning with 323). This will list all 323 references and calculate how much memory has been used. In this example, 21964 bytes have been used.

  Instances of java.util.SimpleTimeZone

  class java.util.SimpleTimeZone

  java.util.SimpleTimeZone@0x004f48c0 (68 bytes)
  java.util.SimpleTimeZone@0x003d5ad8 (68 bytes)
  java.util.SimpleTimeZone@0x004fae88 (68 bytes)
  .....
  Total of 323 instances occupying 21964 bytes.

If you click on one of these SimpleTimeZone instances, you see where this object was allocated.

  Object allocated from:

  java.util.TimeZoneData.<clinit>(()V) :
        TimeZone.java line 1222
  java.util.TimeZone.getTimeZone((Ljava/lang/String;)
	Ljava/util/TimeZone;) :
	TimeZone.java line (compiled method)
  java.util.TimeZone.getDefault(
        ()Ljava/util/TimeZone;) :
	TimeZone.java line (compiled method)
  java.text.SimpleDateFormat.initialize(
        (Ljava/util/Locale;)V) :
	SimpleDateFormat.java line (compiled method)

In this example the object was allocated from TimeZone.java. The source to this file is in the standard src.jar file, and on examining this file, you can see that indeed there are nearly 300 of these objects in memory.

  static SimpleTimeZone zones[] = {
   // The following data is current as of 1998.
   // Total Unix zones: 343
   // Total Java zones: 289
   // Not all Unix zones become Java zones due to
   // duplication and overlap.
   //-------------------------------------------
   new SimpleTimeZone(-11*ONE_HOUR,
                  "Pacific/Niue" /*NUT*/),

Unfortunately, you have no control over the memory used in this example because it is allocated when the program first requests a default timezone. However, this same technique can be applied to analyzing your own application where you may be able to make some improvements

Where the Application Spends its Time

Again, you can use the -Xrunhprof parameter to get information about the time the application spent processing a particular method.

You can use one of two CPU profiling options to achieve this. The first option is cpu=samples. This option reports the result of a sampling of the running threads of the Java VM to which a statistical count of the frequency of the occurrence of a particular method is used to find busy sections of the applications. The second option is cpu=times, which measures the time taken by individual methods and generates a sorted list ranked as a total percentage of the CPU time taken by the application.

By using the cpu=times option, you should see something similiar to this at the end of the output file

CPU TIME (ms) BEGIN (total = 11080)
                       Fri Jan  8 16:40:59 1999
rank   self   accum   count  trace   method
 1   13.81%  13.81%       1   437   sun/
    awt/X11GraphicsEnvironment.initDisplay
 2    2.35%  16.16%       4   456   java/
    lang/ClassLoader$NativeLibrary.load
 3    0.99%  17.15%      46   401   java/
    lang/ClassLoader.findBootstrapClass

If you contrast this with the cpu=samples output, you see the difference between how often a method appears during the runtime of the application in the samples output compared to how long that method took in the times output.

CPU SAMPLES BEGIN (total = 14520)
                   Sat Jan 09 17:14:47 1999
rank  self   accum   count  trace   method
 1    2.93%  2.93%   425    2532    sun/
    awt/windows/WGraphics.W32LockViewResources
 2    1.63%  4.56%   237     763    sun/
    awt/windows/WToolkit.eventLoop
 3    1.35%  5.91%   196    1347    java/
    text/DecimalFormat.<init>

The W32LockView method, which calls a native windows lock routine, is called 425 times. So when it is sampled it appears in the active runnings threads because it also takes time to complete. In contrast, the initDisplay method is only called once, but it is the method that takes the longest time to complete in real time.

This utility can help debug unintentional object retention. This term is used to describe an object that is no longer needed but is kept alive due to references through some path from the rootset. This can happen, for example, if an unintentional static reference to an object remains after the object is no longer needed, if an Observer or Listener fails to de-register itself from its subject when it is no longer needed, or if a Thread that refers to an object does not terminate when it should. Unintentional object retention is the Java language equivalent of a memory leak.

  1. Leave a comment

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: