Profiling in Java
In any Computer Science lectures that has anything to do with the topic
of profiling, the story of how 'awk'
got a performance boost by 25%
just using
gprof
never fails to not be mentioned. The story ends with finding that
offending loop
code
that accounted for most of the wasted computational time.
What makes it such a good story, is probably because that a quarter of the performance drag hinges on just a single line of code. But before anybody starts embarking on their own witch hunts in looking for such performance bottlenecks, I’ll like to remind you about the other story that CS students are always told, the one related to by the ‘Grandpa of Computer Science’, Donald Knuth, on premature optimization:
‘There is no doubt that the ‘grail’ of efficiency leads to abuse. Programmers waste enormous amounts of time thinking about, or worrying about, the speed of noncritical parts of their programs, and these attempts at efficiency actually have a strong negative impact when debugging and maintenance are considered. We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil.’
This is important, because the first thing that a programmer should look out for, is correctness. You can always speculate about where performance bottlenecks are, but unless you’re using something as obvious as a ‘Bubblesort’, you can’t really be sure where the major performance overhead is going to come from.
This is why profilers are handy. It tells you where exactly the performance bottlenecks are, rather than trying to make wild guesses about them before implementation, and writing obscured optimizations that will most likely add unnecessary complexities and potentially introduce more bugs.
Profiling in Java
The equivalent of ‘gprof
’ in the GNU/C world is named,
unimaginatively, as ‘hprof
’ for Java, a natural succession from the
letter 'h'
to 'g'
, just as the 'C'
language is the successor to
'B'
. Gosh, aren’t Computer
Scientists lacking in imagination!
An example syntax for invoking a profiler looks like:
java -agentlib:hprof[=options] ToBeProfiledClass
Hprof allows for the measurement of CPU cycles, Memory Usage, and Thread traces, so it is absolutely helpful in determining the state of the application, and sometimes gives you additional insights in bug tracking either from traces, or locate the sources of memory leaks. I won’t provide more usage details, but a more comprehensive run through of hprof can be found here.
Understanding Hprof’s output
SITES BEGIN (ordered by live bytes) Sat Sep 29 13:46:46 2007
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 18.07% 18.07% 387192 16133 390912 16288 302005 java.lang.String
2 12.04% 30.11% 258144 16134 258144 16134 302007 com.sun.tools.javac.util.List
3 6.14% 36.25% 131512 2 131512 2 301079 com.sun.tools.javac.util.Name[]
4 6.12% 42.36% 131088 1 131088 1 301080 byte[]
5 6.12% 48.48% 131072 1 131072 1 301679 byte[]
6 3.06% 51.54% 65536 1 65536 1 301187 byte[]
7 3.06% 54.59% 65536 1 65536 1 301677 byte[]
8 1.60% 56.19% 34240 428 34800 435 302250 byte[]
9 1.11% 57.30% 23856 426 23856 426 302248 com.sun.tools.javac.code.Symbol$MethodSymbol
The various columns indicates the following:
- rank - self explanatory
- percent self - percentage of memory taken up
- percent accum - cumulative percentage of memory taken up from rank 1 to rank N
- live vs. alloc’ed - the actual objects that are active vs. objects still held in memory i.e, not garbage collected
- stack trace - The corresponding id given to a thread trace that is holding onto a reference to this memory
- class name - The type of object the memory is allocated
A profile dump is only meant to be an indicative measurement of the
application at the given time, so when
you profile is important as well. You’ll most likely want execute
a profile dump when the CPU load is high rather than when it is idle.
The magic keystrokes that allows you to do a dump, is 'ctrl-\'
in
Linux and 'ctrl-break'
in Windows.
Using Hat
Hat
or (JHat
as is now called in Java 6 SE), is a profile analysis
tool which allows you to have make relational queries (like SQL) of
memory usage, which is something that’s pretty interesting.
( Screenshot of Hat’s Web Application Interface )
While I’ve known Hat
for quite a while already, but I have given up a
long time ago for not managing to get it to work. But recently, there is
a new bug
report
filed for the error, which explains the reason for my problem is because
Hat
only being able to read the binary format output from hprof
.
So make sure you have the following parameter for binary format activated:
java -agentlib:hprof=agentlib:hprof=heap=sites,format=b ToBeProfiledClass
If you read the bug report, you’ll realise I wasn’t the only person
being annoyed that such a trivial bug isn’t fixed for such a long time,
not to mention the immense confusion that it’s caused. Perhaps someone
should start renaming JHat
as
‘asshat’ instead!