HPROF is a tool for heap and CPU profiling shipped with every JDK release. It is a dynamic-link library (DLL) that interfaces with the Java Virtual Machine (JVM) using the Java Virtual Machine Tool Interface (JVM TI). The tool writes profiling information either to a file or to a socket in ASCII or binary format. This information can be further processed by a profiler front end tool.
The HPROF tool is capable of presenting CPU usage, heap allocation statistics, and monitor contention profiles. In addition, it can report complete heap dumps and states of all the monitors and threads in the JVM. In terms of diagnosing problems, HPROF is useful when analyzing performance, lock contention, memory leaks, and other issues.
In addition to the HPROF library, the JDK includes the source for HPROF as JVM TI demonstration code. This code is located in the $JAVA_HOME/demo/jvmti/hprof directory.
The following sections describe troubleshooting techniques with HPROF tool.
Invoke the HPROF tool as shown in Example 2-6.
Example 2-6 How to Invoke HPROF Tool
$ java -agentlib:hprof ToBeProfiledClass
$ java -agentlib:hprof=heap=sites ToBeProfiledClass
Depending on the type of profiling requested, HPROF instructs the JVM to send it the relevant events. The tool then processes the event data into profiling information. For example, the following command obtains the heap allocation profile:
The complete list of options is printed when the HPROF agent is provided with the help option, as shown in Example 2-7.
Example 2-7 HPROF Agent Help
$ 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 Oracle 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 JDK.
- 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.
By default, heap profiling information (sites and dump) is written out to java.hprof.txt (in ASCII) in the current working directory.
The output is normally generated when the JVM exits, although this can be disabled by setting the doe (dump on exit) option to n (doe=n). In addition, a profile is generated when Ctrl+\ (on Oracle and Linux operating systems) or Ctrl-Break (on Windows) is pressed. On Oracle Solaris and Linux operating systems a profile is also generated when a QUIT signal is received by a process (kill -QUIT pid). If Ctrl+\ or Ctrl-Break is pressed multiple times, then multiple profiles are generated to the one file.
The output in most cases will contain IDs for traces, threads, and objects. Each type of ID will typically start with a different number than the other IDs. For example, traces might start with 300000.
Example 2-8 is a heap allocation profile generated by running the Java compiler (javac) on a set of input files. Only parts of the profiler output are shown here.
Example 2-8 Heap Allocation Profle
$ javac -J-agentlib:hprof=heap=sites Hello.java
SITES BEGIN (ordered by live bytes) Wed Oct 4 13:13:42 2006
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 44.13% 44.13% 1117360 13967 1117360 13967 301926 java.util.zip.ZipEntry
2 8.83% 52.95% 223472 13967 223472 13967 301927 com.sun.tools.javac.util.List
3 5.18% 58.13% 131088 1 131088 1 300996 byte[]
4 5.18% 63.31% 131088 1 131088 1 300995 com.sun.tools.javac.util.Name[]
A crucial piece of information in the heap profile is the amount of allocation that occurs in various parts of the program. The preceding SITES records show that 44.13% of the total space was allocated for the java.util.zip.ZipEntry objects.
A good way to relate allocation sites to the source code is to record the dynamic stack traces that led to the heap allocation. Example 2-9 shows another part of the profiler output. It illustrates the stack traces referred to by the four allocation sites in the preceding output.
Example 2-9 Profiler Ouput for Stack Traces
TRACE 301926:
java.util.zip.ZipEntry.<init>(ZipEntry.java:101)
java.util.zip.ZipFile+3.nextElement(ZipFile.java:417)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1374)
com.sun.tools.javac.jvm.ClassReader.list(ClassReader.java:1631)
TRACE 301927:
com.sun.tools.javac.util.List.<init>(List.java:42)
com.sun.tools.javac.util.List.<init>(List.java:50)
com.sun.tools.javac.util.ListBuffer.append(ListBuffer.java:94)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1374)
TRACE 300996:
com.sun.tools.javac.util.Name$Table.<init>(Name.java:379)
com.sun.tools.javac.util.Name$Table.<init>(Name.java:481)
com.sun.tools.javac.util.Name$Table.make(Name.java:332)
com.sun.tools.javac.util.Name$Table.instance(Name.java:349)
TRACE 300995:
com.sun.tools.javac.util.Name$Table.<init>(Name.java:378)
com.sun.tools.javac.util.Name$Table.<init>(Name.java:481)
com.sun.tools.javac.util.Name$Table.make(Name.java:332)
com.sun.tools.javac.util.Name$Table.instance(Name.java:349)
Each frame in the stack trace contains a class name, a method name, a source file name, and the line number. The user can set the maximum number of frames collected by the HPROF agent. The default limit is four. Stack traces reveal not only which methods performed heap allocation, but also which methods were ultimately responsible for making calls that resulted in memory allocation.
A heap dump can be obtained using the heap=dump option. The heap dump is in either ASCII or binary format, depending on the setting of the format option. Tools such as jhat use binary format and therefore, the format=b option is required. See The jhat Utility) for more details. When the binary format is specified, the dump includes primitive type instance fields and primitive array content.
Example 2-10 shows the command that produces a complete dump in ASCII text format of the current live objects in the heap from executing the javac compiler:
Example 2-10 Dump in ASCII Text
$ javac -J-agentlib:hprof=heap=dump Hello.java
HEAP DUMP BEGIN (39793 objects, 2628264 bytes) Wed Oct 4 13:54:03 2006
ROOT 50000114 (kind=<thread>, id=200002, trace=300000)
ROOT 50000006 (kind=<JNI global ref>, id=8, trace=300000)
ROOT 50008c6f (kind=<Java stack>, thread=200000, frame=5)
:
CLS 50000006 (name=java.lang.annotation.Annotation, trace=300000)
loader 90000001
OBJ 50000114 (sz=96, trace=300001, class=java.lang.Thread@50000106)
name 50000116
group 50008c6c
contextClassLoader 50008c53
inheritedAccessControlContext 50008c79
blockerLock 50000115
OBJ 50008c6c (sz=48, trace=300000, class=java.lang.ThreadGroup@50000068)
name 50008c7d
threads 50008c7c
groups 50008c7b
ARR 50008c6f (sz=16, trace=300000, nelems=1,
elem type=java.lang.String[]@5000008e)
[0] 500007a5
CLS 5000008e (name=java.lang.String[], trace=300000)
super 50000012
loader 90000001
:
HEAP DUMP END
The output is a large file. It consists of the root set as determined by the garbage collector, and an entry for each Java object in the heap that can be reached from the root set. The following is a selection of records from a sample heap dump.
Each record is a ROOT, OBJ, CLS, or ARR to represent a root, an object instance, a class, or an array. The hexadecimal numbers are identifiers assigned by HPROF. These numbers are used to show the references from an object to another object. In the preceding example, the java.lang.Thread instance 50000114 has a reference to its thread group (50008c6c) and other objects.
In general, as the output is very large, it is necessary to use a tool to visualize or process the output of the heap dump. One such tool is jhat. See The jhat Utility.
The HPROF tool can collect CPU usage information by sampling threads. Example 2-11 shows how to generate a CPU usage sampling profile by running the javac compiler.
Example 2-11 CPU Usage Sampling Profile
$ javac -J-agentlib:hprof=cpu=samples Hello.java
CPU SAMPLES BEGIN (total = 462) Wed Oct 4 13:33:07 2006
rank self accum count trace method
1 49.57% 49.57% 229 300187 java.util.zip.ZipFile.getNextEntry
2 6.93% 56.49% 32 300190 java.util.zip.ZipEntry.initFields
3 4.76% 61.26% 22 300122 java.lang.ClassLoader.defineClass2
4 2.81% 64.07% 13 300188 java.util.zip.ZipFile.freeEntry
5 1.95% 66.02% 9 300129 java.util.Vector.addElement
6 1.73% 67.75% 8 300124 java.util.zip.ZipFile.getEntry
7 1.52% 69.26% 7 300125 java.lang.ClassLoader.findBootstrapClass
8 0.87% 70.13% 4 300172 com.sun.tools.javac.main.JavaCompiler.<init>
9 0.65% 70.78% 3 300030 java.util.zip.ZipFile.open
10 0.65% 71.43% 3 300175 com.sun.tools.javac.main.JavaCompiler.<init>
...
CPU SAMPLES END
The HPROF agent periodically samples the stack of all running threads to record the most frequently active stack traces. The count field above indicates how many times a particular stack trace was found to be active. These stack traces correspond to the CPU usage hot spots in the application.
The HPROF tool can collect CPU usage information by injecting code into every method entry and exit, thereby keeping track of exact method call counts and the time spent in each method. This process uses the bytecode index (BCI) and runs considerably slower than the cpu=samples option. Example 2-12 shows part of the CPU usage times profile output collected from a run of the javac compiler.
Example 2-12 CPU Usage Times Profile
$ javac -J-agentlib:hprof=cpu=times Hello.java
CPU TIME (ms) BEGIN (total = 2082665289) Wed oct 4 13:43:42 2006
rank self accum count trace method
1 3.70% 3.70% 1 311243 com.sun.tools.javac.Main.compile
2 3.64% 7.34% 1 311242 com.sun.tools.javac.main.Main.compile
3 3.64% 10.97% 1 311241 com.sun.tools.javac.main.Main.compile
4 3.11% 14.08% 1 311173 com.sun.tools.javac.main.JavaCompiler.compile
5 2.54% 16.62% 8 306183 com.sun.tools.javac.jvm.ClassReader.listAll
6 2.53% 19.15% 36 306182 com.sun.tools.javac.jvm.ClassReader.list
7 2.03% 21.18% 1 307195 com.sun.tools.javac.comp.Enter.main
8 2.03% 23.21% 1 307194 com.sun.tools.javac.comp.Enter.complete
9 1.68% 24.90% 1 306392 com.sun.tools.javac.comp.Enter.classEnter
10 1.68% 26.58% 1 306388 com.sun.tools.javac.comp.Enter.classEnter
...
CPU TIME (ms) END
In this output, the count represents the true count of the number of times this method was entered, and the percentages represent a measure of thread CPU time spent in this method.
