Tuesday Feb 12, 2008

Using HPROF for finding deadlocks



Most of the information here is based on http://java.sun.com/developer/technicalArticles/Programming/HPROF.html. If you are interested in the complete details about HPROF, please visit that site.

To give you little introduction, HPROF is a memory profiling tool which is loaded in the JVM process context when stated as a command-line option. There are tools such as HAT to analyze the output data. Though a subset of the information such as threads-related and monitors etc are available with a jstack dump, HPROF is , however, preferred for a bigger picture that includes memory-related activities such as heap allocation and CPU profiling.

To run HPROF, use either of the following:

java -agentlib:hprof[=options] ToBeProfiledClass

-OR-

java -Xrunhprof[:options] ToBeProfiledClass

You can get a list of HPROF options by

C:\\Documents and Settings\\Administrator>java -agentlib:hprof=help

     HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)

hprof usage: java -agentlib:hprof=[help]|[<option>=<value>, ...]

Option Name and Value  Description                    Default
---------------------  -----------                    -------
heap=dump|sites|all    heap profiling                 all
cpu=samples|times|old  CPU usage                      off
monitor=y|n            monitor contention             n
format=a|b             text(txt) or binary output     a
file=<file>            write data to file             java.hprof[.txt]
net=<host>:<port>      send data over a socket        off
depth=<size>           stack trace depth              4
interval=<ms>          sample interval in ms          10
cutoff=<value>         output cutoff point            0.0001
lineno=y|n             line number in traces?         y
thread=y|n             thread in traces?              n
doe=y|n                dump on exit?                  y
msa=y|n                Solaris micro state accounting n
force=y|n              force output to <file>         y
verbose=y|n            print messages about dumps     y

Obsolete Options
----------------
gc_okay=y|n

Examples
--------
  - Get sample cpu information every 20 millisec, with a stack depth of 3:
      java -agentlib:hprof=cpu=samples,interval=20,depth=3 classname
  - Get heap usage information based on the allocation sites:
      java -agentlib:hprof=heap=sites classname

Notes
-----
  - The option format=b cannot be used with monitor=y.
  - The option format=b cannot be used with cpu=old|times.
  - Use of the -Xrunhprof interface can still be used, e.g.
       java -Xrunhprof:[help]|[<option>=<value>, ...]
    will behave exactly the same as:
       java -agentlib:hprof=[help]|[<option>=<value>, ...]

Warnings
--------
  - This is demonstration code for the JVMTI interface and use of BCI,
    it is not an official product or formal part of the J2SE.
  - The -Xrunhprof interface will be removed in a future release.
  - The option format=b is considered experimental, this format may change
    in a future release.


You don't really need to compile a java file to use the HPROF. You can use -J option with javac to see the output.

ex. javac -J-agentlib:hprof= ... file.java ( note that there is no space between -J and -agent)

http://java.sun.com/developer/technicalArticles/Programming/HPROF.html very well explains how to gather and analyze the heap dumps and the CPU usage. Therefore, I would cover there how can you use the HPROF to gather information about the threads, deadlocks and monitors etc.

Take a  deadlock situation

I would refer to the code at http://examples.oreilly.com/jenut/Deadlock.java.

Pasting the code from site:

// This example is from _Java Examples in a Nutshell_. (http://www.oreilly.com)
// Copyright (c) 1997 by David Flanagan
// This example is provided WITHOUT ANY WARRANTY either expressed or implied.
// You may study, use, modify, and distribute it for non-commercial purposes.
// For any commercial use, see http://www.davidflanagan.com/javaexamples

/\*\*
 \* This is a demonstration of how NOT to write multi-threaded programs.
 \* It is a program that purposely causes deadlock between two threads that
 \* are both trying to acquire locks for the same two resources.
 \* To avoid this sort of deadlock when locking multiple resources, all threads
 \* should always acquire their locks in the same order.
 \*\*/
public class Deadlock {
  public static void main(String[] args) {
    // These are the two resource objects we'll try to get locks for
    final Object resource1 = "resource1";
    final Object resource2 = "resource2";
    // Here's the first thread.  It tries to lock resource1 then resource2
    Thread t1 = new Thread() {
      public void run() {
        // Lock resource 1
        synchronized(resource1) {
          System.out.println("Thread 1: locked resource 1" )  ;

          // Pause for a bit, simulating some file I/O or something.  
          // Basically, we just want to give the other thread a chance to
          // run.  Threads and deadlock are asynchronous things, but we're
          // trying to force deadlock to happen here...
          try { Thread.sleep(50); } catch (InterruptedException e) {}
          
          // Now wait 'till we can get a lock on resource 2
          synchronized(resource2) {
            System.out.println("Thread 1: locked resource 2" ) ;
          }
        }
      }
    };
   
    // Here's the second thread.  It tries to lock resource2 then resource1
    Thread t2 = new Thread() {
      public void run() {
        // This thread locks resource 2 right away
        synchronized(resource2) {
          System.out.println("Thread 2: locked resource 2" ) ;

          // Then it pauses, for the same reason as the first thread does
          try { Thread.sleep(50); } catch (InterruptedException e) {}

          // Then it tries to lock resource1.  But wait!  Thread 1 locked
          // resource1, and won't release it 'till it gets a lock on
          // resource2.  This thread holds the lock on resource2, and won't
          // release it 'till it gets resource1.  We're at an impasse. Neither
          // thread can run, and the program freezes up.
          synchronized(resource1) {
            System.out.println("Thread 2: locked resource 1" ) ;
          }
        }
      }
    };
   
    // Start the two threads. If all goes as planned, deadlock will occur,
    // and the program will never exit.
    t1.start();
    t2.start();
  }
}


C:\\Documents and Settings\\Administrator>java -agentlib:hprof=monitor=y Deadlock
Thread 1: locked resource 1
Thread 2: locked resource 2
<CTRL> + <BREAK>
2008-02-12 23:59:47
Full thread dump Java HotSpot(TM) Client VM (10.0-b19 mixed mode):

"DestroyJavaVM" prio=6 tid=0x00963800 nid=0xe34 waiting on condition [0x00000000..0x0090fd4c]
   java.lang.Thread.State: RUNNABLE

"Thread-1" prio=6 tid=0x0acff400 nid=0xb44 waiting for monitor entry [0x0b09f000..0x0b09fa94]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at Deadlock$2.run(Deadlock.java:56)
        - waiting to lock <0x06c2ea60> (a java.lang.String)
        - locked <0x06c2ea98> (a java.lang.String)

"Thread-0" prio=6 tid=0x0acfe800 nid=0xc20 waiting for monitor entry [0x0b04f000..0x0b04fb14]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at Deadlock$1.run(Deadlock.java:34)
        - waiting to lock <0x06c2ea98> (a java.lang.String)
        - locked <0x06c2ea60> (a java.lang.String)

"Low Memory Detector" daemon prio=6 tid=0x0ace3c00 nid=0xc78 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x0acd4800 nid=0xb9c waiting on condition [0x00000000..0x0af5f640]
   java.lang.Thread.State: RUNNABLE

"HPROF gc_finish watcher" daemon prio=6 tid=0x0acd3000 nid=0x5d0 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x009f6c00 nid=0xf58 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x009f2c00 nid=0xd1c waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x009e6800 nid=0xdac in Object.wait() [0x0ac1f000..0x0ac1fa94]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x02a90b38> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x02a90b38> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x009e2400 nid=0xd0 in Object.wait() [0x0abcf000..0x0abcfb14]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x02a90a40> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x02a90a40> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x009df400 nid=0x328 runnable

"VM Periodic Task Thread" prio=10 tid=0x0acf6c00 nid=0xc38 waiting on condition


JNI global references: 1339


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x009e66ec (object 0x06c2ea60, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x009e5abc (object 0x06c2ea98, a java.lang.String),
  which is held by "Thread-1"


Java stack information for the threads listed above:
===================================================
"Thread-1":
        at Deadlock$2.run(Deadlock.java:56)
        - waiting to lock <0x06c2ea60> (a java.lang.String)
        - locked <0x06c2ea98> (a java.lang.String)
"Thread-0":
        at Deadlock$1.run(Deadlock.java:34)
        - waiting to lock <0x06c2ea98> (a java.lang.String)
        - locked <0x06c2ea60> (a java.lang.String)

Found 1 deadlock.

Heap
 def new generation   total 960K, used 214K [0x02a90000, 0x02b90000, 0x02f70000)

  eden space 896K,  23% used [0x02a90000, 0x02ac5890, 0x02b70000)
  from space 64K,   0% used [0x02b70000, 0x02b70000, 0x02b80000)
  to   space 64K,   0% used [0x02b80000, 0x02b80000, 0x02b90000)
 tenured generation   total 4096K, used 0K [0x02f70000, 0x03370000, 0x06a90000)
   the space 4096K,   0% used [0x02f70000, 0x02f70000, 0x02f70200, 0x03370000)
 compacting perm gen  total 12288K, used 1660K [0x06a90000, 0x07690000, 0x0aa900
00)
   the space 12288K,  13% used [0x06a90000, 0x06c2f2a8, 0x06c2f400, 0x07690000)
No shared spaces configured.

Dumping contended monitor usage ... done.

Note: you can either collect the stats at the end of the program or you can use Ctrl-\\ (on Solaris) or by typing Ctrl-Break (on Win32) to dump the conent in between


You can see above that HPROF has detected the deadlock. If you want to analyze the java.hprof.txt you can have a look below



Analyzing the output (java.hprof.txt)
=============================

THREAD START (obj=50000138, id = 200003, name="Signal Dispatcher", group= "system";)
THREAD START (obj=50000138, id = 200004, name="Attach Listener", group= "system";)
THREAD START (obj=50000138, id = 200002, name="HPROF gc_finish watcher", group ="system";)
THREAD START (obj=50000138, id = 200001, name="main", group ="main";)
THREAD START (obj=5000015e, id = 200005, name="Thread-0", group ="main";)
THREAD START (obj=5000015e, id = 200006, name="Thread-1", group ="main";)
THREAD END (id = 200001)
THREAD START (obj=50000138, id = 200007, name="DestroyJavaVM", group ="main";)

The threads of our interest are main (id = 200001) , Thread-0 ( id = 200005) and Thread-1 (id = 200006). It shows that the SIGQUIT signal

Explanation of Thread states
=======================

R — Runnable
S — Suspended
CW — Condition Wait
MW — Monitor Wait
ZO - Zombie

monitor dump
============

MONITOR DUMP BEGIN
    THREAD 200001, trace 300000, status: ZO
    THREAD 200002, trace 300000, status: R
    THREAD 200003, trace 300000, status: R
    THREAD 200004, trace 300000, status: R
    THREAD 200005, trace 300029, status: MW
    THREAD 200006, trace 300030, status: MW
    THREAD 200007, trace 300000, status: R
    MONITOR Ljava/lang/String;
    owner: thread 200005, entry count: 1
    waiting to enter: thread 200006
    waiting to be notified:
    MONITOR Ljava/lang/String;
    owner: thread 200006, entry count: 1
    waiting to enter: thread 200005
    waiting to be notified:
MONITOR DUMP END


The above shows that both Monitors are of type String and first monitor is owned by Thread-0 and Thread-1 is waiting to enter into it. The second monitor shows exactly the opposite.

About

This is the blog of a software engineer, specialized in identity management. Kunal Sinha works in Directory Services Engineering (OpenDS) team from Austin,Texas.

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today
Bookmarks