Trace Entries Section

While profile information is being recorded, HPROF generates a number of trace entries, which are simply stack traces like those you've seen when an uncaught exception is thrown by your application. Each trace created by HPROF is assigned a unique identifier value, and as we'll see later, trace identifiers can be useful in determining which execution paths represent hot spots within your application. An example of a trace entry created by HPROF is shown overleaf:

TRACE 1856:
java/lang/String.toCharArray(String.java:1899)
java/lang/Thread.init(Thread.java:268)
java/lang/Thread.<init>(Thread.java:398)
ThreadTest.main(ThreadTest.java:7)

This particular trace entry has been assigned an identifier value of 1856, and it represents the execution of line 1899 within the String class, and that line is part of the toCharArray() method. That method was in turn called from line 268 of the Thread class, and that line is part of the init() method, which was in turn called from line 398 of a Thread constructor ("<init>"), etc.

Each line that identifies a class, method, source file, and line is called a frame, and there are four frames in the above example. By default, HPROF generates up to four frames for each trace entry, although as we'll see you can increase or decrease that value if it's helpful to do so.

The depth Option

You can use this option to specify the maximum number of frames that will be included in each trace entry. The default value for this parameter is four, and you will not normally need to increase that value unless four frames do not supply enough information to allow you to uniquely identify an execution path.

The lineno Option

Each frame normally includes the line number that was executed, but you can use this option to suppress the line numbers from the output listing. When you do so, each frame will contain the text "Unknown line" instead of the line number:

TRACE 1056:
java/util/Locale.toUpperCase(Locale.java:Unknown line)
java/util/Locale.<init>(Locale.java:Unknown line)
java/util/Locale.<clinit>(Locale.java:Unknown line)
sun/io/CharacterEncoding.aliasName(CharacterEncoding.java:Unknown line)

The thread Option

HPROF always records the thread summary information in its report, but by default does not associate the trace entries with a specific thread. This is not a problem if your application is single-threaded in nature, but if your code supports multiple threads, it can be helpful for the trace entries to identify the thread with which they're associated. When thread=y is specified, each trace entry contains additional text that includes the identifier value of the thread associated with the entry as shown below:

TRACE 1910: (thread=8)
java/lang/Object.wait(Object.java:Native method)
java/lang/Object.wait(Object.java:424)
ThreadTest.run(ThreadTest.java:20)
java/lang/Thread.run(Thread.java:479)
TRACE 1664: (thread=1)
java/lang/StringBuffer.toString(StringBuffer.java:1063)
java/io/BufferedReader.readLine(BufferedReader.java:Compiled method)
java/io/BufferedReader.readLine(BufferedReader.java:329)
java/util/Properties.load(Properties.java:179)

Monitor Dump Section

The monitor dump section of HPROF output displays the status of each thread and a report of the monitors that are owned by threads and for which threads have invoked the wait() method. To provide an example of this output, we'll run a slightly modified version of the ThreadTest class defined earlier. This application will start two threads that execute an object's run() method, and once inside that method, the threads will invoke wait(). After a brief delay, the main thread that started those two new threads will wake up one of the threads with a call to notify(), but in this case, that thread will call sleep() instead of exiting:

public class ThreadTest implements Runnable {

public static void main(String[] args) {
 ThreadTest tt = new ThreadTest();
 Thread t1 = new Thread(tt, "First");
 t1.setDaemon(true);
 Thread t2 = new Thread(tt, "Second");
 t2.setDaemon(true);
 t1.start();
 t2.start();
 try {
  Thread.sleep(2000);
 } catch (Exception e) {}
 ;
 synchronized (tt) {
  tt.notify();
 } 
 try {
  Thread.sleep(2000);
 } catch (Exception e) {}
 ;
} 

public synchronized void run() {
 try {
  wait();
 } catch (InterruptedException ie) {}
 ;
 sleepAWhile(5000);
} 

protected synchronized void sleepAWhile(long time) {
 try {
  Thread.sleep(time);
 } catch (Exception e) {}
 ;
} 

}

If this application is run with HPROF enabled, it will produce the following thread summary:

THREAD START (obj=835e60, id = 2, name="Signal dispatcher", 
group="system")
THREAD START (obj=8367c0, id = 3, name="Reference Handler", 
group="system")
THREAD START (obj=83a700, id = 4, name="Finalizer", group="system")
THREAD START (obj=8b17c0, id = 5, name="SymcJIT-LazyCompilation-PA", 
group="main")
THREAD START (obj=8b2cb0, id = 6, name="HPROF CPU profiler", 
group="system")
THREAD START (obj=830e70, id = 1, name="main", group="main")
THREAD START (obj=8ece00, id = 7, name="First", group="main")
THREAD START (obj=8ec940, id = 8, name="Second", group="main")
THREAD START (obj=8b1e00, id = 9, name="SymcJIT-LazyCompilation-0", 
group="main")
THREAD END (id = 1)
THREAD START (obj=8edb00, id = 10, name="Thread-0", group="main")
THREAD END (id = 10)

Unfortunately, at the time of writing the JDK 1.3 "Hotspot" virtual machine fails with an internal error when using the monitor dump HPROF option. This problem does not occur when using the -classic option to turn off the Hotspot JVM. This bug occurs in Sun's bug database (Bug ID 4378856).

In addition, the HPROF output will include the monitor dump information listed below:

MONITOR DUMP BEGIN
 THREAD 11, trace 1896, status: R
 THREAD 8, trace 1897, status: CW
 THREAD 7, trace 1898, status: CW
 THREAD 6, trace 1899, status: MW
 THREAD 9, trace 1888, status: CW
 THREAD 5, trace 1900, status: CW
 THREAD 4, trace 1901, status: CW
 THREAD 3, trace 1902, status: CW
 THREAD 2, trace 1903, status: R
 MONITOR ThreadTest(8ecb50)
owner: thread 7, entry count: 2
waiting to be notified: thread 8
 MONITOR SymantecJITCompilationThread(8b1e00) unowned
waiting to be notified: thread 5
 MONITOR java/lang/ref/Reference$Lock(836b00) unowned
waiting to be notified: thread 3
 MONITOR java/lang/ref/ReferenceQueue$Lock(8392a0) unowned
waiting to be notified: thread 4
 RAW MONITOR "_Hprof CPU sampling lock"(0x8b2f70)
owner: thread 6, entry count: 1
 RAW MONITOR "SymcJIT Lazy Queue Lock"(0x8b1d34) unowned
waiting to be notified: thread 9
 RAW MONITOR "_hprof_dump_lock"(0x7d0ef0)
owner: thread 11, entry count: 1
waiting to enter: thread 6
 RAW MONITOR "Monitor cache lock"(0x7d0df0)
owner: thread 11, entry count: 1
 RAW MONITOR "Thread queue lock"(0x7d0cc0)
owner: thread 11, entry count: 1
 RAW MONITOR "Monitor registry"(0x7d0c70)
owner: thread 11, entry count: 1
MONITOR DUMP END

The first portion of the monitor dump identifies each active thread, its state, and the trace entry that identifies the code the thread executed. The thread's state will be one of the following four values, although you should not normally see suspended threads in Java 2 applications:

The second section of the monitor dump identifies the monitors that are currently owned and those that one or more threads are currently waiting on. In this case, the first thread created by our ThreadTest application owns the monitor of the ThreadTest object. The second thread had previously obtained the monitor, but implicitly released it by invoking the ThreadTest object's wait() method and is now waiting to be notified. The states of these two threads are reflected in the first entry in the monitor dump, which indicates that thread 7 owns the monitor of the ThreadTest object at location 8ecb50, as shown below:

MONITOR ThreadTest(8ecb50)
owner: thread 7, entry count: 2
waiting to be notified: thread 8

The entry count refers to the number of nested synchronized blocks the owner thread has entered, and is used by the Java Virtual Machine to determine when a thread should release the monitor. For example, when thread 7 first entered the run() method and successfully obtained the monitor, the entry count value was set to one. However, once that thread executed the sleepAWhile() method, which is synchronized on the same object, the entry count value was incremented to two. When the thread exits sleepAWhile(), the entry count will be reduced to one, and when it exits the run() method, the count will be decremented to zero and the monitor released.

The monitor Option

While HPROF is capable of including a monitor dump section in its report, it does not do so by default. To include the monitor information, you must include monitor=y in the list of parameters.

Heap Dump Section

The heap dump is perhaps the most complex part of the output generated by HPROF, but in practice, you will not normally need to analyze it. However, we'll look briefly at some of the entries you'll find.

The heap dump is simply a list of the areas of memory that are allocated at the time that the profile information is recorded, and describes areas allocated for class definitions, objects, and arrays. These types are identified in the HPROF output with the abbreviations CLS, OBJ, and ARR, respectively, and each entry includes information that describes how it is used. For example, entries like those shown below are added to the output the first time an instance of java.util.Vector is created:

CLS 7b6ac0 (name=java/util/Vector, trace=10)
super  7b8530
constant[6] 7a58a0
constant[10] 7b9290
constant[13] 7a4de0
constant[16] 7c2240
constant[19] 7b8530
constant[23] 7b99d0
constant[25] 7b6ac0
CLS 7b8530 (name=java/util/AbstractList, trace=10)
super  7b8f00
constant[6] 7b8f00
constant[7] 7b8530
constant[12] 7b99d0
CLS 7b8f00 (name=java/util/AbstractCollection, trace=10)
super  7a4de0
constant[6] 7a4de0
constant[11] 7b8f00
constant[12] 7b93c0
CLS 7b93c0 (name=java/util/Collection, trace=10)
super  7a4de0
constant[2] 7b93c0
CLS 7b99d0 (name=java/util/List, trace=10)
super  7a4de0
constant[2] 7b93c0
constant[3] 7b99d0
CLS 7b9290 (name=java/lang/Cloneable, trace=10)
super  7a4de0
constant[1] 7b9290
OBJ 7ba560 (sz=20, trace=11, class=java/util/Vector@7b6ac0)
elementData 7ba6a0
ARR 7ba6a0 (sz=44, trace=12, nelems=10, elem type=java/lang/Object@7a4de0)
[0]  83d8f0
[1]  84b640

The first entry represents the Vector class definition and describes the address at which it is located. In addition, it identifies the trace entry that corresponds to this memory allocation, the address of the class definition of Vector's superclass, and points to the constants defined in Vector. Constants include string and numeric constant values defined within the Vector class, and the superclass address is simply the pointer to the class definition of Vector's superclass, which is AbstractList. The second entry in the above listing is a CLS entry for AbstractList, because that class must also be loaded before an instance of Vector can be created. In fact, the entire superclass hierarchy from Vector to Object, and all the implemented interfaces, must be loaded although no entry for the Object class definition appears in the above section because it was already loaded.

Once the hierarchy of class definitions has been loaded, the instance of Vector is created as illustrated by the OBJ entry shown above. If you examine the source code for Vector, you'll find that it has three instance fields defined like those shown below:

protected Object[] elementData;
protected int elementCount;
protected int capacityIncrement;

The two primitive values (elementCount and capacityIncrement) are stored in the area allocated for the Vector instance, but a separate area is allocated for the array of Object instances, and that fact is reflected in the ARR entry.

Continued...