JDK Debugging Tools

Joey Shen, Sang Shin, sang.shin@sun.com, Sun Microsystems, www.javapassion.com

   

In this lab, you are going to exercise basic features of command line debugging tools that come with Java SE 6, which includes jps, jmap, jconsole, jhat, jstat, and jstack.  You are also going to exercise how to use JConsole to detect "OutOfMemory" case and Deadlock detection.

Expected duration: 60 minutes (excluding homework)


Software Needed

Before you begin, you need to install the following software on your computer. 


OS platforms you can use

Change Log


Lab Exercises


Exercise 0: Get yourself familiarized with Java SE command line debugging tools


1. From your browser, go to Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.  Spend some time reading and browsing the document.

Exercise 1: Use Java SE Command line Debugging Tools


In this lab, you are going to exercise basic features of command line debugging tools that come with Java SE 6, which includes jps, jmap, jconsole, jhat, jstat, and jstack.
  1. Build "AnagramGame" application through NetBeans and run at the command line
  2. Use "jps"
  3. Use "jconsole"
  4. Use "jmap" with heap dump option
  5. Use "jmap" with history option
  6. Use "jhat"
  7. Use "jstat"
  8. Use "jstack"

(1.1) Build "AnagramGame" application through NetBeans and run at the command line


In this exercise, we are going to use AnagramGame application as a target application against which you are going to use JDK command line debugging tools.  You can certainly use another application as a target application.  In that case, you can skip this step.

1. Create a new NetBeans project.

Figure-1.10: Create a New NetBeans project

Figure-4.11: Select Anagram Game sample application

Figure-4.12: Finish creating the project

2. Make sure the project is using JDK 6.

3. Build the project.


Figure-4.14: Take the command line

4. Run the program external to the NetBeans IDE.

Note: If you are running on FAT32 system on Windows, type java -XX:+PerfBypassFileSystemCheck -jar "C:\myprojects\AnagramGame\dist\anagrams.jar".




                                                                                                              return to top of the exercise

(1.2) Use "jps"


The jps utility lists the instrumented HotSpot Virtual Machines for the current user on the target system.  The utility is very useful in environments where the VM is embedded, that is, it is started using the JNI Invocation API rather than the java launcher. In these environments it is not always easy to recognize the Java processes in the process list.

For further documentation on "jps", please read Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.

C:\handsonlabs\javase6tools>jps -help
usage: jps [-help]
       jps [-q] [-mlvV] [<hostid>]

Definitions:
    <hostid>:      <hostname>[:<port>]

C:\handsonlabs\javase6tools>jps
2748 Jps
2520 Main
5092 anagrams.jar

C:\handsonlabs\javase6tools>jps -l
2284 sun.tools.jps.Jps
2520 org/netbeans/Main
5092 C:\myprojects\AnagramGame\dist\anagrams.jar

C:\handsonlabs\javase6tools>jps -lv
4628 sun.tools.jps.Jps -Denv.class.path=.;C:\Program Files\Java\jre1.6.0_01\lib\ext\QTJava.zip -Dapp
lication.home=c:\Progra~1\Java\jdk1.6.0_03 -Xms8m
2520 org/netbeans/Main -Dnetbeans.importclass=org.netbeans.upgrade.AutoUpgrade -Dnetbeans.accept_lic
ense_class=org.netbeans.license.AcceptLicense -Dorg.netbeans.modules.tomcat.autoregister.token=11968
94955156 -Dorg.netbeans.modules.tomcat.autoregister.catalinaHome=C:\Program Files\Apache Software Fo
undation\Apache Tomcat 6.0.14 -Dcom.sun.aas.installRoot=C:\Program Files\glassfish-v2 -Xss2m -Xms32m
 -XX:PermSize=32m -XX:MaxPermSize=200m -Xverify:none -Dapple.laf.useScreenMenuBar=true -Xmx369m -XX:
+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -Djdk.home=C:\Progr
am Files\Java\jdk1.6.0_03 -Dnetbeans.home=C:\Program Files\NetBeans 6.0\platform7 -Dnetbeans.dirs=C:
\Program Files\NetBeans 6.0\nb6.0;C:\Program Files\NetBeans 6.0\ide8;C:\Program Files\NetBeans 6.0\j
ava1;C:\Program Files\NetBeans 6.0\xml1;C:\Program Files\NetBeans 6.0\apisupport1;C:\Program Files\N
etBeans 6.0\enterprise4;C:\Program Files\NetBeans 6.0\mobility8;C:\Program Files\NetBeans 6.0\profil
er2;C:\Program Files\NetBeans 6.0\ruby1;C:\Prog
5092 C:\myprojects\AnagramGame\dist\anagrams.jar

C:\handsonlabs\javase6tools>



                                                                                                              return to top of the exercise


(1.3) Use "jconsole"


For detailed documentation on "jconsole", please read Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.

1. Start JConsole.



2. Analyze the data.



                                                                                                              return to top of the exercise


(1.4) Use "jmap" with heap dump option


You can perform the following tasks with the "jmap".
For further documentation on "jmap", please read Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.

For practical usage example of "jmap" and "jhat", please see Using Mustang's jmap/jhat to profile GlassFish blog by Jean-Francois Arcand.

C:\Documents and Settings\sang>jmap -help
Usage:
    jmap -histo <pid>
      (to connect to running process and print histogram of java object heap
    jmap -dump:<dump-options> <pid>
      (to connect to running process and dump java heap)

    dump-options:
      format=b     binary default
      file=<file>  dump heap to <file>

    Example:       jmap -dump:format=b,file=heap.bin <pid>

C:\Documents and Settings\sang>jmap -dump:format=b,file=c:\tmp\myheap.bin 320
Dumping heap to C:\tmp\myheap.bin ...
Heap dump file created

C:\Documents and Settings\sang>dir \tmp\myheap.bin
 Volume in drive C is ACER
 Volume Serial Number is 2B8C-2F19

 Directory of C:\tmp

12/11/2007  04:19 AM         4,403,304 myheap.bin
               1 File(s)      4,403,304 bytes
               0 Dir(s)   6,749,487,104 bytes free



                                                                                                              return to top of the exercise



(1.5) Use "jmap" with history option



C:\Documents and Settings\sang>jmap -histo 320|more

num   #instances    #bytes  class name
--------------------------------------
  1:      5005      521384  <constMethodKlass>
  2:      5005      401160  <methodKlass>
  3:      7184      338744  <symbolKlass>
  4:      4192      295584  [C
  5:       623      293192  <constantPoolKlass>
  6:       889      243088  [B
  7:       623      243040  <instanceKlassKlass>
  8:       586      193520  <constantPoolCacheKlass>
  9:      1790      143200  java.lang.reflect.Method
 10:      4335      104040  java.lang.String
 11:       893       87160  [I
 12:       838       80448  java.lang.Class
 13:       953       68616  java.lang.reflect.Field
 14:      1451       67248  [Ljava.lang.Object;
 15:       206       65920  <objArrayKlassKlass>
 16:       611       58048  [Ljava.util.HashMap$Entry;
 17:       918       46152  [S
 18:      1784       42816  java.util.HashMap$Entry
 19:      1116       15164  [[I
 20:      1996       35640  [Ljava.lang.Class;



                                                                                                              return to top of the exercise


(1.6) Use "jhat"


The "jhat" let you parse a binary heap dump, launch a web browser, and present standard queries.  Specifically you can perform the following tasks with the "jhat".
For further documentation on "jhat", please read Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.

1. jhat -help

C:\Documents and Settings\sang>jhat -help
Usage:  jhat [-stack <bool>] [-refs <bool>] [-port <port>] [-baseline <file>] [-debug <int>] [-version] [-h|-help] <file>

        -J<flag>          Pass <flag> directly to the runtime system. For
                          example, -J-mx512m to use a maximum heap size of 512MB
        -stack false:     Turn off tracking object allocation call stack.
        -refs false:      Turn off tracking of references to objects
        -port <port>:     Set the port for the HTTP server.  Defaults to 7000
        -exclude <file>:  Specify a file that lists data members that should
                          be excluded from the reachableFrom query.
        -baseline <file>: Specify a baseline object dump.  Objects in
                          both heap dumps with the same ID and same class will
                          be marked as not being "new".
        -debug <int>:     Set debug level.
                            0:  No debug output
                            1:  Debug hprof file parsing
                            2:  Debug hprof file parsing, no server
        -version          Report version number
        -h|-help          Print this help and exit
        <file>            The file to read

For a dump file that contains multiple heap dumps,
you may specify which dump in the file
by appending "#<number>" to the file name, i.e. "foo.hprof#3".

All boolean options default to "true"

C:\Documents and Settings\sang>jhat c:\tmp\myheap.bin
Reading from c:\tmp\myheap.bin...
Dump file created Tue Dec 11 04:19:04 EST 2007
Snapshot read, resolving...
Resolving 46044 objects...
Chasing references, expect 9 dots.........
Eliminating duplicate references.........
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.



2. Access the data from the browser.




3. OQL

select f.referent from java.lang.ref.SoftReference f 
where f.referent != null





                                                                                                              return to top of the exercise


(1.7) Use "jstat"


For further documentation on "jstat", please read Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.

C:\Documents and Settings\sang>jstat -help
Usage: jstat -help|-options
       jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

Definitions:
  <option>      An option reported by the -options option
  <vmid>        Virtual Machine Identifier. A vmid takes the following form:
                     <lvmid>[@<hostname>[:<port>]]
                Where <lvmid> is the local vm identifier for the target
                Java virtual machine, typically a process id; <hostname> is
                the name of the host running the target Java virtual machine;
                and <port> is the port number for the rmiregistry on the
                target host. See the jvmstat documentation for a more complete
                description of the Virtual Machine Identifier.
  <lines>       Number of samples between header lines.
  <interval>    Sampling interval. The following forms are allowed:
                    <n>["ms"|"s"]
                Where <n> is an integer and the suffix specifies the units as
                milliseconds("ms") or seconds("s"). The default units are "ms".
  <count>       Number of samples to take before terminating.
  -J<flag>      Pass <flag> directly to the runtime system.

C:\Documents and Settings\sang>jstat -options
-class
-compiler
-gc
-gccapacity
-gccause
-gcnew
-gcnewcapacity
-gcold
-gcoldcapacity
-gcpermcapacity
-gcutil
-printcompilation

C:\Documents and Settings\sang>jstat -gc 5092
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT
 64.0   64.0   0.0    64.0   896.0    896.0     4096.0     397.6    12288.0 271.2       1    0.005 0      0.000    0.005

C:\Documents and Settings\sang>jstat -gcutil 5092
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
  0.00 100.00 100.00   9.71   2.21      1    0.005     0    0.000    0.005

C:\Documents and Settings\sang>jstat -gcnew 5092
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005

C:\Documents and Settings\sang>jstat -gcnew -h3 5092 250
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
  64.0   64.0    0.0   64.0  1  15   32.0    896.0    896.0      1    0.005
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT



                                                                                                              return to top of the exercise

(1.8) Use "jstack"


For further documentation on "jstack", please read Detailed Tool Description section of the Troubleshooting Guide for Java SE 6 with HotSpot document.'

C:\Documents and Settings\sang>jstack 5092|more
2008-02-13 23:59:53
Full thread dump Java HotSpot(TM) Client VM (1.6.0_03-b05 mixed mode, sharing):

"TimerQueue" daemon prio=6 tid=0x031bc000 nid=0x1280 in Object.wait() [0x0349f000..0x0349fd94]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x22a07500> (a javax.swing.TimerQueue)
        at javax.swing.TimerQueue.run(TimerQueue.java:236)
        - locked <0x22a07500> (a javax.swing.TimerQueue)
        at java.lang.Thread.run(Thread.java:619)

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

"AWT-EventQueue-0" prio=6 tid=0x031a7000 nid=0xf00 in Object.wait() [0x033df000..0x033dfa14]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x22ea71b0> (a java.awt.EventQueue)
        at java.lang.Object.wait(Object.java:485)
        at java.awt.EventQueue.getNextEvent(EventQueue.java:479)
        - locked <0x22ea71b0> (a java.awt.EventQueue)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:245)
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:183)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:173)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:168)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:160)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:121)

"AWT-Windows" daemon prio=6 tid=0x02afc800 nid=0xbcc runnable [0x02ecf000..0x02ecfa94]
   java.lang.Thread.State: RUNNABLE
        at sun.awt.windows.WToolkit.eventLoop(Native Method)


Summary

In this exercise,  you have exercised various Java SE 6 command line debugging tools.

                                                                                                                        return to the top


Exercise 2: Memory Consumer


In this exercise, you are going to see how memory is being consumed by running an application that continously consumes heap space memory. You will also learn how to use JConsole to observe the memory consumption behavior of the application.
  1. Display Call stack on OutOfMemoryError exception (due to the lack of heap space)
  2. Display Call stack on OutOfMemoryError exception (due to the lack of perm space)
  3. Use JConsole to monitor the memory usage
  4. Display JVM data through JMX

(2.1) Display Call stack on OutOfMemory exception (due to the lack of heap space)


1. Open MemoryConsumer NetBeans project. 
2. Observe the preset VM Options.



3. Run the application.




<Learning point: Call stack on OutOfMemoryError exception> From this example, we can see, in Java SE 6, as far as the information provided on OutOfMemoryError exception is concerned, there is a huge improvement.  When an error occurs, the system produces error message with call stack as shown below, from which you can see where in your program the memory is being requested at the time of the exception.

Exception in thread "AWT-EventQueue-0" java.lang.OutOfMemoryError: Java heap space
        at java.util.Arrays.copyOfRange(Arrays.java:3209)
        at java.lang.String.<init>(String.java:216)
        at java.lang.StringBuilder.toString(StringBuilder.java:430)
        at memory.MyObject.<init>(MemoryConsumer.java:401)
        at memory.MemoryConsumer.jButton4ActionPerformed(MemoryConsumer.java:316)
        at memory.MemoryConsumer.access$000(MemoryConsumer.java:16)
        at memory.MemoryConsumer$1.actionPerformed(MemoryConsumer.java:97)
        at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:1995)
        ...


4. Study the offending code.

class MyObject {
    private String s;
    static int i = 10000000;

    public MyObject() {
        StringBuilder sb = new StringBuilder(1000000);
        String number = String.valueOf(i++);
        while (sb.length() < (1000000 - number.length())) {
            sb.append(number);
        }
        s = sb.toString();
    }
   
    public static int getCount() {
        return i;
    }
   
    public void intern() {
        s = s.intern();
    }
}


5. Close the application.



(2.2) Display Call stack on OutOfMemoryError exception (due to the lack of PermGen space)


1. Run MemoryConsumer application with Non Heap Memory.



<Learning point: PermGen space> 

The detail message PermGen space indicates that the permanent generation is full. The permanent generation is the area of the heap where class and method objects are stored. If an application loads a very large number of classes, then the size of the permanent generation might need to be increased using the -XX:MaxPermSize option.

Interned java.lang.String objects are also stored in the permanent generation. The java.lang.String class maintains a pool of strings. When the intern method is invoked, the method checks the pool to see if an equal string is already in the pool. If there is, then the intern method returns it; otherwise it adds the string to the pool. In more precise terms, the java.lang.String.intern method is used to obtain the canonical representation of the string; the result is a reference to the same class instance that would be returned if that string appeared as a literal. If an application interns a huge number of strings, the permanent generation might need to be increased from its default setting.

When this kind of error occurs, the text String.intern or ClassLoader.defineClass might appear near the top of the stack trace that is printed.

The jmap -permgen command prints statistics for the objects in the permanent generation, including information about internalized String instances. See 2.6.4 Getting Information on the Permanent Generation.

We can see the OutOfMemoryError is not due to the lack of Heap anymore, but due to the lack of PermGen space.  Through analyzing the call stack, we can see the the exception occurred because the jButton5ActionPerformed method kept creating new MyObject object instances.  Taking a closer look at MyObject.intern(), we can see this method perform intern task on every MyObject containing String with length  of 1,000,000.

2. Close the application.

(2.3) Using JConole to monitor the internal memory while the program is running.


1. Start the MemoryConsumer application again.
2. Connect JConsole to the MemoryConsumer application..


3. Observe the memory usage patterm.  In JConole's summary, there are 4 graphs. They individually reflect the Heap memory usage,  Threads, Classes, and CPU Usage.



4. Study the Memory usage.


5. Use up the Heap Memory.


(2.4) Display JVM data through JMX


In this step, you are going to display various management information through built-in MXBean in modern JVM.  You still need to write some code to access the data that is collected by the MXBean.

1. Get TODO lists.



2. Add code to the first TODO.
<Learning point: MemoryMXBean> If you want to access through JMX the data collected by the JVM, you get the relevant MXBean through MangementFactory. The MemoryMXBean collects the memory usage data in the JVM. Other examples of MXbean include ClassLoadingMXBean, ThreadMXBean, RuntimeMXBean, OperatingSystemMXBean, GarbageCollectorMXBean, MemoryManagerMXBean, MemoryPoolMXBean.

    Map<Integer, MyObject> map = new HashMap<Integer, MyObject>();
  
    //TODO: get an instance of MemoryMXBean here
    MemoryMXBean mb = ManagementFactory.getMemoryMXBean();
3. Add code to the second TODO.
    private void updateUI() {
        //TODO: get snapshot of memory usages for both heap and non-heap
        MemoryUsage heapmem = mb.getHeapMemoryUsage();
        MemoryUsage nonheap = mb.getNonHeapMemoryUsage();

        //TODO: connect memory information to jLabels accordingly


4. Add code to the third TODO.
        //TODO: get snapshot of memory usages for both heap and non-heap
        MemoryUsage heapmem = mb.getHeapMemoryUsage();
        MemoryUsage nonheap = mb.getNonHeapMemoryUsage();
      
        //TODO: connect memory information to jLabels accordingly
        jLabel2.setText(NumberFormat.getInstance().format(heapmem.getInit()));
        jLabel5.setText(NumberFormat.getInstance().format(heapmem.getMax()));
        jLabel8.setText(NumberFormat.getInstance().format(heapmem.getCommitted()));
        jLabel11.setText(NumberFormat.getInstance().format(heapmem.getUsed()));
        jLabel14.setText(NumberFormat.getInstance().format(nonheap.getInit()));
        jLabel17.setText(NumberFormat.getInstance().format(nonheap.getMax()));
        jLabel20.setText(NumberFormat.getInstance().format(nonheap.getCommitted()));
        jLabel23.setText(NumberFormat.getInstance().format(nonheap.getUsed()));
    }


.

5. Add an action handler to GC button.

The MemoryMXBean provides gc(0) method and forces JVM to perform garbage collection. 


   private void jButton2ActionPerformed(java.awt.event.ActionEvent evt) {
        // TODO add your handling code here:
        mb.gc();
    }


6. Run the application.





7. Connect JConole to the MemoryConsumer Application.

Summary

In this exercise,  you have learned how the heap space and PermGen spaces are consumed.  You also learned how to use JConsole to display the memory usage of the JVM.  Finally you also learned how to access built-in system MXBean's to access the information on the JVM.

                                                                                                                        return to the top

Exercise 3: Deadlock detection


In this exercise, you are going to perform deadlock detection through JConsole.
  1. Build and run DeadlockThreads application.
  2. Use JConsole to detect a deadlock
  3. Analyze the code

(3.1) Build and run DeadlockThreads application


1. Open DeadlockThreads NetBeans project. 
2. Run the DeadlockThreads application.

(3.2) Use JConsole to detect a deadlock


1. Start JConsole.


2. Detect deadlock.




(3.3) Analyze the code


1. Open DeadlockThreads.java.

package deadlock;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

/**
 *
 * @author root
 */
public class DeadlockThreads {

    public static void main(String[] args) {
        final Friend alphonse = new Friend("Alphonse");
        final Friend gaston = new Friend("Gaston");

        ExecutorService es = Executors.newFixedThreadPool(2);
        es.execute(new Runnable() {

            public void run() {
                alphonse.bow(gaston);
            }
        });

        es.execute(new Runnable() {

            public void run() {
                gaston.bow(alphonse);
            }
        });
    }
}

class Friend {
    private final String name;

    public Friend(String name) {
        this.name = name;
    }

    public String getName() {
        return this.name;
    }

    public synchronized void bow(Friend bower) {
        try {
            System.out.printf("%s: %s has bowed to me!%n",
                    name, bower.getName());
            Thread.sleep(1000);
            bower.bowBack(this);
        } catch (InterruptedException ex) {
            ex.printStackTrace();
        }
    }

    public synchronized void bowBack(Friend bower) {
        System.out.printf("%s: %s has bowed back to me!%n",
                this.name, bower.getName());
    }
}

Summary

In this exercise,  you have learned how to use JConsole to detect a deadlock.

                                                                                                                        return to the top

Homework Exercise (for people who are taking Sang Shin's "Advanced Java Programming online course")


<to be provided>

                                                                                                                        return to the top