USFJProf Documentation

Version 1.0

Introduction

USFJProf is a code profiling tool that grew out of a masters project class in the Fall of 2003. Until recently, there weren't any good free profiling tools for Java (people tell us that Eclipse has a good plug-in these days that is supposed to work well with the Java VM). Besides costing money, profilers don't seem to do everything a programmer needs. Just about every profiler uses a statistical approach for timing info in that the system "wakes up" every n milliseconds and asks "where am I"? Your "timing" results are actually just ratios of the overall time spent in the various methods. USFJProf takes a more deterministic approach; it translates your source code in order to instrument it with calls to our profiler to track method invocations and object creations. Consequently, USFJProf can tell you precisely how many times a method is called, which methods it calls, how long each method takes, etc...

The disadvantage of the deterministic approach is that the timing results are affected by the garbage collection, multiple threads, on-the-fly compilation, and even basic system load. On a lightly loaded system, however, we've not gotten wild fluctuations in our results. When you are really interested in the timing for a method we provide a -focus argument that records the time measurements for every single invocation of that method. If you change the starting Java heap size and rerun the same program with the same data, any differences in the focus time measurements are purely due to random system events or the garbage collector.

Feature summary

This profiling tool instruments java source code with profiling methods. The instrumented code is then compiled and called to run from within the profiling tool. Profiling information is recorded. Results are dumped once the program ends.

We have borrowed Vladimir Roubtsov's native timer code for both Windows and Linux due to the inaccuracy of the standard Java timing method (System.currentTimeInMillis()). If the application can not find the native timer library, the standard Java timing method will be used instead.

Features of the profiling tool include:

• Count number of times each method is called.
• Count average/min/max time spent within a method.
• Count average/min/max time spent within a method, excluding time spent on other methods included in tracking.
• Display which, and how many, methods are called from within a method.
• Display which, and how many, objects are created from within a method.
• Display which, and how many, constructors are called from within a method.
• Allow user to specify what packages or files to be included or excluded from tracking.
• Allow user to choose methods on which the output could be focused: both inclusive and exclusive time for every calls to these methods will be outputted to files.
• Allow user to write output to a file.
• Instrumented code can be run as a standalone java application.

Setup guide

Using Java's clock

If you are running under linux or any other system that does not need the native code to directly access the system clock, then all you need is usfjprof.jar and antlr.jar from ANTLR.org (at least version antlr-2.7.3rc3) in your CLASSPATH. Unfortunately, Java's clock has millisecond not microsecond resolution. This is the least desirable option, but easiest to set up. Both jars are included in this distribution.

Native clock

To use the system clock directly you must get the native code by Vladimir Roubtsov from his My kingdom for a good timer! article. The Java library for native timer need to be placed in Java lib path. The windows library is lib/hrtlib.dll, and the Linux library is lib/libhrtlib.so.

To use native clock on Linux:

Set current directory to main jprof directory (the root of the USFJProf software) and then do this:

LD_LIBRARY_PATH=`pwd`/lib
export LD_LIBRARY_PATH

In case you want to compile the lib file:

gcc -o libhrtlib.so -shared -Wl,-soname,libhrt.so -I/usr/java/j2sdk1.4.2/include -I/usr/src/linux/include com_vladium_utils_timing_HRTimer.c -static -lc

Assuming "/usr/java/j2sdk1.4.2" is your java directory.

Windows:

Set current directory to system path if you have your windows lib file here:

set PATH=%PATH%;./

In case you want to compile the lib file: (we did not try this, but we assume this works.)

cl -Ic:/jdk1.4.2/include
-Ic:/jdk1.4.2/include/win32
-LD com_vladium_utils_timing_HRTimer.c -hrtlib.dll

Assuming "/j2sdk1.4.2" is your java directory.

Usage

Run the profiling tool:

java edu.usfca.jprof.Profile <options> <class> <args>

<options> are:

-src <dirs> : indicate where to find source files. The source directories should be the top level of your packages. Use semicolon to separate. The default source directory is the top level of the main program's package

-output <filename> : Output profiling information to <filename> instead of standard output.

-include <packages>: Include packages or files. Only included packages or files will be tracked. Use semicolon to separate. Default: all source directories

-exclude <packages>: Exclude packages or files. Track all packages or files except these ones. Use semicolon to separate. Default: none

-native true : Whether to use native clock. Default: -native false

-focus <methodNames> : Focus on a list of fully-qualified method names, meaning that inclusive and exclusive running time for all calls to the method(s) will be written into a log file. Use semicolon to separate the method names. The output for each method is written to methodname.log. methodName can be either with an argument list, -focus mypackage.Test.foo(int), or without, -focus mypackage.Test.foo. The latter one will log all methods named package.Test.foo regardless of the method signature.

-d usfjprof.jikes=<value>: Allow user to compile instrumented java code with jikes. <value> is the directory containing jikes executable file. Default: javac is used.

-help : Print this help message

<class>: the main program to profile
<args>: the arguments to <class>

Please note: order matters when both -include and -exclude are specified as command line arguments. Generally, the first one should be broader than the second one. For instance, -include foo.bar.* -exclude foo.bar.A means include all files in foo.bar package, but exclude foo.bar.A.

Use fully qualified class names for arguments of include, exclude and focus.

Examples:

java edu.usfca.jprof.Profile -src "foo" -include "foo.bar.*" \
    -exclude "foo.bar.A" foo.bar.Main

java edu.usfca.jprof.Profile -src "foo" -include "foo.bar.*" \
    -exclude "foo.bar.A;foo.bar.B" \
    -focus "foo.bar.Main.loop(int)" foo.bar.Main

Run instrumented code:

You can also run the instrumented code from the command line (without going through the Profile class) just like running any other java application. In order to do this, you need to have directory usfjprofwork under system temporary directory placed at the BEGINNING of your classpath. To do this:

On Linux:

CLASSPATH=/tmp/usfjprofwork:$CLASSPATH
export CLASSPATH

On Windows:

set classpath=%temp%;%classpath%

Output

The output displays four parts, separated by comments (delimited by "#").

Part 1: methods execution time. Columns are:

Method name | number of times called | inclusive: average | min | max | exclusive: average | min | max

Part 2: number of methods being called from within the method. Columns are:

Method name | (method name | times ) *

Part 3: constructor calls from within the method. Columns are:

Method name | (constructor name | times ) *

Part 4: object created from within the method. Columns are:

Class name | number of instances

Log file for focused methods will show method name, inclusive and exclusive execution time for each call to the method. Columns are:

Method name | inclusive time | exclusive time

Example

The following was run from the main jprof directory, which contains the test directory.

$ java edu.usfca.jprof.Profile -src test test/Loop 1000
Translating java files...
Starting translated program...
# ========================= Thread main =============================

# Method execution time in ms: 
# method name | times called | inclusive: average | min | max | exclusive: average | min | max

test.Loop.loop(int) 1 412.0000 412.0000 412.0000 183.0000 183.0000 183.0000 
test.Loop.main(String[]) 1 413.0000 413.0000 413.0000 1.0000 1.0000 1.0000 
test.Loop.task() 1000 1.0510 1.0000 51.0000 1.0510 1.0000 51.0000 

#
----------------------------------------------------------------------
# Number of methods called: 
# method name | (method name | times) *

test.Loop.loop(int) test.Loop.task() 1000 
test.Loop.main(String[]) test.Loop.loop(int) 1 

#
----------------------------------------------------------------------
# of constructors called: 
# method name | (constructor name | times) *


#
----------------------------------------------------------------------
# Number of instances created: 
# class name | (number of instances) *

int[][] 1000 
test.Test 1 

Sorting Output

The output of this tool is unordered so you must decide how you want it sorted and then using Microsoft Excel (it knows how to pull in space-separated data) or command line tools on Linux, reorder it yourself. You can save the result to a file, for example:

java edu.usfca.jprof.Profile -src test test/Loop 1000 > profile_result

$ cat method-timing-from-usfjprof | \
    awk '{print $2, $1;}' | \  # print method count, name
    sort -r -n                 # sort reverse numeric

51726 JavaLexer.nextToken()
24058 JavaLexer.mWS(boolean)
21332 JavaLexer.mIDENT(boolean)
17941 JavaTreeParser.primaryExpression(AST)
17402 JavaTreeParser.expr(AST)
15737 JavaRecognizer.unaryExpressionNotPlusMinus()
...

$ cat method-timing-from-usfjprof | \
    awk '{print $6, $1;}' | \  # print avg exclusive time, name
    sort -r -n                 # sort reverse numeric
10.3438 JavaTreeParser.arrayInitializer(AST)
7.0000 JavaTreeParser.interfaceBlock(AST)
3.1667 JavaLexer
2.0000 Main.main(String[])
2.0000 Main.doFile(File)
1.0000 Main.windowClosing(WindowEvent)
1.0000 Main.parseFile(String,Reader)
1.0000 JavaTreeParser.importDefinition(AST)
...

Known issues

Currently, the source to source profiling tool is not able to give accurate timing information when multithreading is used, nor do we exclude garbage collection, JIT compilation time. Further, without using native code to check the microsecond clock, results will appear to be 0.00ms for most small routines. A millisecond is an eternity to modern processors. Also, of note, is that we cannot profile programs that require standard input.