Reminder: Look at <file:/home/jake/CSC/index.html> for updates or corrections!
Goal: Get a feel for how profiling tools show you how a program behaves
First, create a local copy of the exercise files.
cd
tar xf ~jake/CSC/exercise5.tar
cd exercise5
source setup.sh
Take a look at the TestHprof.java file. Assume you wanted to concatenate “more” to a string 5000 times. There are several ways to do this, and the TestHprof class contains methods for each of them:
makeString: Invoke an “addToCat” subroutine to do the concatenation
makeStringInline: Write a simple concatenation operation in a single statement.
cat = cat+”more”;
makeStringWithLocal: Use a simple concatentation operation, but with a temporary variable
makeStringWithBuffer: Explicitly address the StringBuffer used by the string
You can see how the programmer’s thinking might have gone. “makeString” is the obvious way to start. Concerned about performance, he/she might have decided to get rid of the function call, resulting in “makeStringInline”. Perhaps using a local temporary variable would result in some efficiency, so “makeStringWithLocal” is tried. And then, having finally read the Sun recommendations, he/she realizes that those all use a temporary String variable. Accessing the original StringBuffer object avoids that, requiring less memory management of temporary objects, so “makeStringWithBuffer” was written.
We’ll profile this to see how much of a difference this makes. First, we compile and run it:
javac *.java
time ./run
The “run” script just runs java with the profiling options. That will take a little while. Preceeding it with “time” prints a report of how long it took to complete. When it completes, you’ll have a new “java.hprof.txt” file containing the raw profile information. Take a look at its structure, in particular the measurements at the end.
To browse this information in a more usable form, we run PerfAnal:
./analysis
The “analysis” script just invokes the PerfAnal class with java. The four windows shown in lecture will appear on your screen. The upper left one, “Method Times by Caller”, shows that almost all of the time is used in TestHProf; the rest is spent in loading java classes, etc. If you click on the folder by TestHProf, you’ll see how it is spending its time.
(Note: These instructions were written before we were sure how fast the School machines would be. If the program is so fast that you’re not getting good information, change the line:
public final static int loop=5000;
to have a higher number of passes through the loop. It might be reasonable to move that up to 20000,
for example).
Using this you can already tell that the “makeStringWithBuffer” is by far the fastest, often so fast that it doesn’t even show up in the profile. There’s not much difference between the other methods. You might conclude from this that somehow memory management of temporary items takes a lot of time. Examine the slower routines carefully to see if this is true.
The “Method Times by Callee” window answers the question “Who is asking for this work to be done?” You should see “java.lang.StringBuffer.append” as using almost all of the time. Open it, and you’ll find that the bulk of the time is divided among three of the string-making methods. A few other uses show up, probably from string manipulations while the program was starting up.