Java Profiling with hprof

Ok. I learned something today. I hadn't known that JVM had always included in it a tool for profiling and monitoring Heap and CPU. It seems that we are always fighting preformance problems with Java/J2EE apps. HPROF does come in handy for situations like this. HPROF provides simple profiling based on command line arguments supplied at JVM startup.

Here is how I used it to profile a simple Java application:

java -Xrunhprof:cpu=samples,heap=sites,file=classFinder_profiled.log SomeClass

Some key things to observe in the output:

SITES BEGIN (ordered by live bytes) Mon Nov 22 11:24:13 2004
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 22.88% 22.88% 253704 2602 8184488 73802 345 [C
2 22.88% 45.76% 253632 2601 8184488 73802 343 [C
3 16.90% 62.66% 187344 2602 5313744 73802 346 java.util.zip.ZipEntry
4 5.63% 68.29% 62448 2602 1771248 73802 344 java.lang.String
5 4.55% 72.85% 50488 234 50672 240 1 [B
6 4.48% 77.33% 49712 371 50976 397 1 [C
7 2.81% 80.14% 31128 485 621408 497 1 [I
8 2.54% 82.68% 28168 222 29616 251 1 [C
9 2.23% 84.91% 24776 312 24776 312 1 [S

Note the memory allocation that occurs in various parts of the program. The above log shows for example that 16.9% of the total space was allocated for java.util.zip.ZipEntry objects at a particular SITE (a unique stack trace of a fixed depth). The live data figure differs from the total allocated figure, which means that a garbage collection has probably not happened before HPROF iterated over the heap.

There is a lot of useful stuff to pore over in this log. Check it out for yourself. The other thing to note is that these JVM args do affect the performance of your app - obviously because of the large amount of data collection that is involved while running the app.

In Java 5.0 this HPROF has been re-implemented, but I haven't experimented with that yet. We are still in 1.4.1 land in our project, and I don't see us upgrading in the near future.