HPROF A Heap / CPU profiling Tool

HPORF is actually used to work out which parts of a program are using the most memory or processor time.  To improve the efficiency of our application we should know what part of the code are using large amount of memory and CPU resource.

HPROF is actually a JVM native agent library which is dynamically loaded through a command line option, at JVM startup, and becomes part of the JVM process.  By supplying HPROF options at startup, users can request various types of heap and CPU profiling features.  The data generated can be in textual or binary format, and can be used to track down and isolate performance problems involving memory usage and inefficient code.

Java –Xrunhprof[<option>=<value>,…] <classname>

When we run Java with HPROF, an output file is created at the end of program execution.  This file is placed in the current working directory and is called java.hprof.txt (java.hprof if binary format is used) unless a different filename has been given.  This file contains a number of different sections, but the exact format and content depend on the selected options.

The command java –Xrunhprof:help display the options avaialbe

D:\KalGyan>java -Xrunhprof: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 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.

heap=dump|sites|all

This option helps in the analysis of memeory usage.  It tells HPROF to generate stack traces, from which we can see where memory was allocated.  If we use the heap=dump option, we get a dump of all reachable objects in the heap.  With heap=sites, we get a sorted list of sites with the most heavily allocated objects at the top.

cpu=samples|times|old

The cpu option outputs information that is useful in determining where the CPU spends most of its time.  If cpu is set to “samples”, the JVM pauses execution and identifies which method call is active.  If the sampling rate is high enough, we get a good picture o where our program spends most of its time.  If cpu is set to “timing”, we receive precise measurements of how many times each method was called and how long each execution took.  Although this is more accurate, it slows down the program.  If cpu is set to “old” the profiling data is output in the old hprof format.

monitor=y|n

The monitor option can help us to understand how synchronization affects the performance of our application.  Monitors are used to implement thread synchronization so getting information on monitors can tell us how much time different threads are spending when trying to access resources that are already locked.  HPROF also give us a snapshot of the monitors in use and it is useful for detecting deadlocks.

format= a|b

The default is for the output file to be in ASCII format.  Set format to ‘b’ if we want to specify a binary format.

file =<filename>

The file option lets us change the name of the output file.  The default name for an ASCII file is java.hprof.txt.  The default name for a binary files is java.hprof

net=<host>:<port>

To send the output over the network rather than to local file we can use this net option.

depth=<size>

The depth option indicates the number of method frames to display in a stack trace

thread =y | n

If we set the thread option to ‘y’ then the thread id is preinted besided each trace.  This option is useful if it is not clear which thread is associated with which trace.  This can be an issue in a multi-threaded application.

doe= y | n

The default beavhiour is to collect profile information when an application exits.  To collect the profiling data during executing we set doe (dump on exit) to ‘n’.

Let see few examples on the HPROF with their options

Heap allocation profile (heap=sites)

Command used: javac -J-agentlib:hprof=heap=sites TestKalGayn.java

SITES BEGIN (ordered by live bytes) Fri Oct 22 11:52:24 2004
          percent          live          alloc'ed  stack class
 rank   self  accum     bytes objs     bytes  objs trace name
    1 44.73% 44.73%   1161280 14516  1161280 14516 302032 java.util.zip.ZipEntry
    2  8.95% 53.67%    232256 14516   232256 14516 302033 com.sun.tools.javac.util.List
    3  5.06% 58.74%    131504    2    131504     2 301029 com.sun.tools.javac.util.Name[]
    4  5.05% 63.79%    131088    1    131088     1 301030 byte[]
    5  5.05% 68.84%    131072    1    131072     1 301710 byte[]

When java.hprof.txt file is generated when stack will appear in this way:

TRACE 302032:

        java.util.zip.ZipEntry.<init>(ZipEntry.java:101)

        java.util.zip.ZipFile$3.nextElement(ZipFile.java:435)

        java.util.zip.ZipFile$3.nextElement(ZipFile.java:413)

        com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1442)

TRACE 302033:

        com.sun.tools.javac.util.List.<init>(List.java:43)

        com.sun.tools.javac.util.List.<init>(List.java:51)

        com.sun.tools.javac.util.ListBuffer.append(ListBuffer.java:98)

        com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1442)

If we want to create dump file then we will go with following command

Command used: javac -J-agentlib:hprof=heap=dump TestKalGayn.java

To get CPU sampling profiles (cpu=samples)

Command used: javac -J-agentlib:hprof=cpu=samples TestKalGyan.java


CPU SAMPLES BEGIN (total = 126) Fri Oct 22 12:12:14 2004

rank   self  accum   count trace method

   1 53.17% 53.17%      67 300027 java.util.zip.ZipFile.getEntry

   2 17.46% 70.63%      22 300135 java.util.zip.ZipFile.getNextEntry

   3  5.56% 76.19%       7 300111 java.lang.ClassLoader.defineClass2

   4  3.97% 80.16%       5 300140 java.io.UnixFileSystem.list

   5  2.38% 82.54%       3 300149 java.lang.Shutdown.halt0

   6  1.59% 84.13%       2 300136 java.util.zip.ZipEntry.initFields

   7  1.59% 85.71%       2 300138 java.lang.String.substring

   8  1.59% 87.30%       2 300026 java.util.zip.ZipFile.open

   9  0.79% 88.10%       1 300118 com.sun.tools.javac.code.Type$ErrorType.<init>

  10  0.79% 88.89%       1 300134 java.util.zip.ZipFile.ensureOpen

To get CPU usage time profile (cpu=times)

Command used: javac -J-agentlib:hprof=cpu=times TestKalGayn.java


CPU TIME (ms) BEGIN (total = 103099259) Fri Oct 22 12:21:23 2004

rank   self  accum   count trace method

   1  5.28%  5.28%       1 308128 com.sun.tools.javac.Main.compile

   2  5.16% 10.43%       1 308127 com.sun.tools.javac.main.Main.compile

   3  5.15% 15.58%       1 308126 com.sun.tools.javac.main.Main.compile

   4  4.07% 19.66%       1 308060 com.sun.tools.javac.main.JavaCompiler.compile

   5  3.90% 23.56%       1 306652 com.sun.tools.javac.comp.Enter.main

   6  3.90% 27.46%       1 306651 com.sun.tools.javac.comp.Enter.complete

   7  3.74% 31.21%       4 305626 com.sun.tools.javac.jvm.ClassReader.listAll

   8  3.74% 34.95%      18 305625 com.sun.tools.javac.jvm.ClassReader.list

   9  3.24% 38.18%       1 305831 com.sun.tools.javac.comp.Enter.classEnter

  10  3.24% 41.42%       1 305827 com.sun.tools.javac.comp.Enter.classEnter

  11  3.24% 44.65%       1 305826 com.sun.tools.javac.tree.Tree$TopLevel.accept

  12  3.24% 47.89%       1 305825 com.sun.tools.javac.comp.Enter.visitTopLevel

  13  3.23% 51.12%       1 305725 com.sun.tools.javac.code.Symbol.complete

  14  3.23% 54.34%       1 305724 com.sun.tools.javac.jvm.ClassReader.complete

  15  3.23% 57.57%       1 305722 com.sun.tools.javac.jvm.ClassReader.fillIn

  16  1.91% 59.47%      16 305611 com.sun.tools.javac.jvm.ClassReader.openArchive

  17  1.30% 60.78%     330 300051 java.lang.ClassLoader.loadClass

  18  1.28% 62.06%     330 300050 java.lang.ClassLoader.loadClass

  19  1.22% 63.28%     512 300695 java.net.URLClassLoader.findClass

  20  1.21% 64.48%     512 300693 java.net.URLClassLoader$1.run

  21  1.09% 65.57%   14516 305575 java.util.zip.ZipFile$3.nextElement

  22  0.98% 66.55%   14516 305574 java.util.zip.ZipFile$3.nextElement

  23  0.96% 67.52%       1 304560 com.sun.tools.javac.main.JavaCompiler.instance

  24  0.96% 68.48%       1 304559 com.sun.tools.javac.main.JavaCompiler.<init>

  25  0.71% 69.19%     256 302078 java.net.URLClassLoader.access$100