We discussed in previous entries on "Understanding the performance of your application on the IBM Java 5.0 and 6.0 JVMs" and "Using method profiling in Health Center to improve Java code performance" how the sample based method profiling in HealthCenter can be used to diagnose and fix performance problems in Java code in Java 5.0 and Java 6.0.
This leaves the question: What can I used to profile performance problems on earlier releases of Java where HealthCenter is unavailable?
Sample based profiling for Java 1.4.2: TPROF
One option for sample based profiling at Java 1.4.2 is Time Profiler (TPROF) which is part of the Performance Inspector package of tools available from sourceforge.net.
TPROF is a system profiling tool available for AIX, Linux, Windows and z/OS that records what process, thread and code is executing on CPU(s) using time based sampling. This provides information on what C language functions are executing and occupying CPU time, and with the addition of an agent into the Java process will provide information on what Java language methods are executing.
Enabling Java method sampling in TPROF
In order to track the Java methods being executed in addition to the C functions a TPROF agent, supplied as part of the package from the Performance Inspector tools site, needs to be loaded into the Java process. This can be done as follows:
For Java 5.0 and earlier:
java -Xrunjprof:tprof,fnm=D:\ibmperf\bin\log,pidx AppNameFor Java 5.0 and later:
java -agentlib:jprof=tprof,fnm=D:\ibmperf\bin\log,pidx AppNameIf you are running Java on AIX, a version of TPROF is available as part of the operating system install.
Information of setting up and using the AIX TPROF to profile Java applications is available in the Java Troubleshooting Guide.
Running TPROF to sample the Java application
Once the Java application has been started with the TPROF agent loaded, you need to start the TPROF data gathering process, which will begin sampling the data from the system. The most simple mode for running tprof is using:
run.tprofThis will prompt you the following prompts to start tracing:
\****\* \****\* ***** Press ENTER when ready to begin tracing or Ctrl-C to quit ...and to stop tracing:
\****\* \****\* ***** Tracing. Press ENTER when ready to stop ...and will create a trace file and a tprof.out file, which is the report of the data gathered by TPROF.
TPROF in trace only mode using the "-t" flag, which produces just the trace file which has be post processed later using run.tprof with the "-p" option. The start and stop of the data gathering can also be set automatically using the "-s" flag which sets a delay time to start profiling and the the "-r" option to specify the time to gather data for:
run.tprof -t s10 -r 60This will run TPROF for 60 seconds from roughly 10 seconds after the run.tprof command is entered, and product a raw trace file called swtrace.nrm2 which can then be post processed to produce the report file using:
run.tprof -pWhich will create the tprof.out file from the swtrace.nrm2 file.
More information on running TPROF is available from the Performance Inspector website.
Interpreting the tprof.out report
The TPROF report is broken down into sections. The section that is the closest equivalent to that provided by HealthCenter is the Process Module Symbol section, which shows the highest used Java methods or C functions on a per process basis.
Looking up the Java process, you get the following kind of output:
================================ )) Process_Module_Symbol ================================ LAB TKS %%% NAMES PID 5028 85.26 java.exe_138c MOD 2374 40.26 JITCODE SYM 489 8.29 java/util/regex/Pattern.compile()V_1c237b0 SYM 370 6.27 java/util/regex/Pattern.atom()Ljava/util/regex/Pattern$Node; _1c274ec SYM 179 3.04 java/util/regex/Pattern.sequence(Ljava/util/regex/Pattern$Node; )Ljava/util/regex/Pattern$Node;_1c24758 SYM 144 2.44 java/util/regex/Pattern.closure(Ljava/util/regex/Pattern$Node; )Ljava/util/regex/Pattern$Node;_1c17d3c SYM 135 2.29 java/io/BufferedReader.readLine(Z)Ljava/lang/String; _1c284bc SYM 113 1.92 java/util/regex/Pattern$Curly.match0(Ljava/util/regex/Matcher;IILjava/lang/CharSequence;)Z_1c291dc SYM 97 1.64 java/util/regex/Pattern.newSlice([IIZ)Ljava/util/regex/Pattern$Node; _1c1953c SYM 91 1.54 java/util/regex/Pattern.matcher(Ljava/lang/CharSequence; )Ljava/util/regex/Matcher;_1c2e19c SYM 87 1.48 java/util/regex/Matcher.This gives a very similar output to what we saw previously when running with HealthCenter, with the majority of the time being spent in the compile() method of java.util.regex.Pattern.
(Ljava/util/regex/Pattern;Ljava/lang/CharSequence; )V_1c22e28 SYM 63 1.07 sun/io/ByteToCharSingleByte.convert([BII[CII)I_1c219d4 SYM 57 0.97 java/util/regex/Pattern$Ctype.match(Ljava/util/regex/Matcher;ILjava/lang/CharSequence; )Z_1c19ebc SYM 53 0.90 java/util/regex/Matcher.match(II)Z_1c1df90 SYM 52 0.88 java/io/BufferedReader.readLine(Z)Ljava/lang/String;_1c30e30
Differences between TPROF and HealthCenter
HealthCenter has a number of advantages for Java method profiling over TPROF:
- HealthCenter provides a live view, whereas TPROF only provides snapshots from a given sample period
- HealthCenter has an Invocation Paths view, which shows the call relationships between methods (which method is calling which method)