Profiling Java methods with the heap profiling agent


The Java SDK comes with a number of tools and JVM options that can be used to analyze the performance of the Java runtime. One extremely useful tool is the heap profiler agent, which provides facilities to profile memory usage, CPU utilization and lock contention. To load the profiler agent to profile CPU utilization, you can add the “-agentlib:hprof=cpu=times” option to your java command line:

$ java -Xms256m -Xmx256m -verbose:gc -agentlib:hprof=cpu=times App

Once loaded, the agent will use byte code injection (BCI) to instrument each method’s entry and return points. This allows the agent to measure the number of times each method was called, the time spent in each method, and the call chain that led to the method being invoked. To utilize the agent to it’s full potential, you will need to exercise the application while the agent is active. Once the runtime has been exercised, you can hit cntrl+C to stop the process. This will cause the agent to write the data it has collected to the file java.hprof.txt, which can be viewed with your favorite pager or editor:

$ more java.hprof.txt

CPU TIME (ms) BEGIN (total = 40712194) Mon Jan 21 19:23:12 2008
rank self accum count trace method
1 38.52% 38.52% 1036273 301143 java.util.Random.next
2 19.57% 58.09% 518136 301144 java.util.Random.nextDouble
3 11.87% 69.96% 518136 301145 java.lang.Math.random
4 11.05% 81.01% 1036274 301141 java.util.concurrent.atomic.AtomicLong.get
5 10.53% 91.54% 1036273 301142 java.util.concurrent.atomic.AtomicLong.compareAndSet
6 8.14% 99.68% 259068 301146 TestMain.foo
7 0.05% 99.73% 1 300969 java.security.Permissions.add
8 0.04% 99.77% 1 301106 java.lang.Class.privateGetDeclaredFields
9 0.03% 99.79% 1 301138 java.util.Random.
10 0.02% 99.81% 2 300908 java.io.FilePermission$1.run
11 0.01% 99.82% 1 301283 java.lang.ThreadGroup.remove
12 0.01% 99.83% 1 300820 sun.net.www.protocol.file.Handler.createFileURLConnection
......

The java.hprof.txt file contains the number of times each method was invoked, as well as the amount of CPU time (as a percentage) that was spent in each method. To see how a method was called, you can search the profiler output for the trace identifier that is listed along side the profiling data. This will produce a Java stack trace similar to the following that shows how a given method was invoked:

TRACE 301143:
java.util.Random.next(Random.java:Unknown line)
java.util.Random.nextDouble(Random.java:Unknown line)
java.lang.Math.random(Math.java:Unknown line)
TestMain.foo(TestMain.java:Unknown line)

The BCI approach introduces a fair amount of overhead to the Java runtime. In cases were the overhead is hindering testing, you can use the agent’s “cpu=samples” option instead. This will cause the agent to sample the runtime environment at periodic intervals to see which methods are executing. While this approach is not as accurate as the BCI approach, it provides a good set of results with less runtime overhead. The java profiling agent is incredibly useful, and just one of the vast number of tools that are available to profile Java applications.

This article was posted by Matty on 2008-02-02 15:05:00 -0400 -0400