Java Method Trace for IBM JVMs

Resolving The Problem

Invoking Method Trace
Method trace is invoked by adding additional system properties to the command line of the Java process or to the parameters array if a JNI launcher is being used.

The required options are as follows:

-Dibm.dg.trc.print=MT
-Dibm.dg.trc.methods=[!][*]class[*].[*]method[*][()]

Where:

!	is a logical not. i.e. the class/methods specified immediately following are deselected for method trace
*	is a wildcard that can appear at the beginning and/or end of the class and method names
class	is the package or class name in slash form. eg. java/Lang/String
.	is the delimiter between class and method name
method	is the method name
()	are left and right parenthesis. This specifies that input parameters should be traced where possible

For example:

• Select all methods for all classes:
  
  -Dibm.dg.trc.methods=*
  
  
• All methods in java/lang/String. In addition, input parameters should be traced:
  
  -Dibm.dg.trc.methods=java/lang/String.*()
  
  
• All methods that contain a "y" in classes starting with com/ibm:
  
  -Dibm.dg.trc.methods=com/ibm*.*y*
  
  
• All methods that contain a "y" and don't start with an "n" in classes starting with com/ibm
  
  -Dibm.dg.trc.methods=com/ibm*.*y*,!com/ibm*.n*

Creating a Trace Properties File
Rather than adding multiple system properties to the command line, it is possible to use the following single command line option to cause further properties to be loaded from a trace properties file.

-Dibm.dg.trc.properties=filename

Where:

filename

is the name of the trace properties file, including any path to the file

For example:

• Load trace.prop from the current directory:
  
  -Dibm.dg.trc.properties=trace.prop
  
  
• Load traceprops from /tmp:
  
  -Dibm.dg.trc.properties=/tmp/traceprops

The format of this file is a flat ASCII/EBCDIC file containing trace properties, which can be abbreviated to remove the initial ibm.dg.trc string.

Therefore:

-Dibm.dg.trc.print=MT
-Dibm.dg.trc.methods=java/lang/String.*()

Would become:

print=MT
methods=java/lang/String.*()


Logging the Trace to a File
By default, the trace will be written as formatted flat ASCII/EBCDIC text to stderr as a result of using the "print" property. Alternatively, it is possible to log the trace to an output file by exchanging "print" for "maximal" and adding the following system property:

-Dibm.dg.trc.output=trace_filespec[,nnnm[,generations]]

This property indicates that trace data should be directed to trace_filespec. If the file doesn't already exist it will be created; otherwise it will be overwritten.

The file can be limited to nnn megabytes, at which point it will wrap non-destructively to the beginning; otherwise it will grow until disk space is exhausted.

Generations may be specified as a value between 2 and 36 inclusive. This causes up to 36 files to be used in a round-robin fashion as each file reaches its size threshold. When a file needs to be reused, it is overwritten; this implies that if x generations of n megabyte files are specified, the worst case is that only ((x - 1) * n / x ) megabytes of trace data may be available. If generations is specified, the filename must contain a "#" (hash, pound symbol), which will be substituted with its generation identifier, the order of which is 0-9 followed by A-Z.

The trace_filespec may also contain the %p and %d substitutions. These will be replaced by the process ID and timestamp as determined at the startup of the process.

N.B. When tracing to a file, buffers for each thread are written when the buffer is full or when the JVM terminates. If a thread has been inactive for a period of time prior to JVM termination, what appears to be 'old' trace data will be written to the file. When formatted, it will then appear that trace data is missing from the other threads, but this is an unavoidable side-effect of the buffer per thread design. This becomes especially noticeable when using the generation facility, and formatting individual earlier generations.

For example:

-Dibm.dg.trc.maximal=MT

used in conjunction with one of the following output options:

• Trace output goes to /u/traces/gc.problem - no size limit :
  
  -Dibm.dg.trc.output=/u/traces/gc.problem
  
  
• Output goes to trace and will wrap at 2mb:
  
  -Dibm.dg.trc.output= trace,2m
  
  
• Output goes to gc0.trc, gc1.trc, gc2.trc, each 10mb in size:
  
  -Dibm.dg.trc.output=gc#.trc,10m,3

Formatting a Trace Output File
The trace output files are stored as a binary representation of the trace data, and therefore must be formatted to become human readable. For this the trace formatter is used.

The trace formatter is a java program that runs on any platform and is capable of formatting a trace file from any platform. The formatter, which is shipped with the SDK, also requires a file called TraceFormat.dat which contains the formatting templates and resides in sdk/jre/lib.

The trace formatter is invoked using:

java [-Dibm.dg.trc.format=traceformat_dir] com.ibm.jvm.format.TraceFormat input_filespec [output_filespec] [options]

Where:

traceformat_dir	is the directory in which the TraceFormat.dat file resides. This defaults to sdk/jre/lib
input_filespec	is the name of the binary trace file to be formatted. To format an entire generational trace, use the name as specified on the output trace property, including the #. Alternatively, specify the name of the specific generation to format. Note that in the latter case, trace data may appear to be missing from threads that have not yet written their buffers.
output_filespec	is the optional output filename

With options:

-summary	specifies that a summary of the trace file is printed
-entries:comp[,...]	specifies that only trace entries for component comp are to be formatted
-thread:threadid,..	specifies that only entries for threadid are to be formatted (threadid is specified as 0xnnnnnnnn)
-indent	specifies the trace data is to be indented on entry type tracepoints and outdented on exit type tracepoints. This may produce undesirable results on selective traces where, say, exits from a function are not traced, but entries are.
-symbolic	specifies that the symbolic name of the tracepoint is embedded in the trace output. This is useful where the descriptive text for a particular tracepoint do not make it clear what is being traced.

Using Trigger Trace (1.4.x only)
As of 1.4.1 it is possible to trigger certain events to occur when particular trace points are hit.
These events can be used to generate javacore.txt file, headump.txt files, system dumps or to suspend and resume trace. This last option can be useful to minimise the trace output and generate trace data for only the scenario you are interested in.

The property that invokes this functionality is described below:

-Dibm.dg.trc.trigger=clause[,clause][,clause]

NB - This property does not control what is traced. It merely controls whether what has been selected by the other trace properties is produced as normal or whether it is blocked.

The clause parameter is used to define a trigger point, and the action that should be associated with reaching that point:

method(methodspec,[entryAction],[exitAction][,delayCount])

On encountering the specified active method, or a method defined by a range of methods, the specified action will be performed. If a delayCount is specified, the action will be performed only after the JVM encounters such an active method that many times.

Wherever an action must be specified, the user must select from the following choices:

suspend	Suspend ALL tracing (except for special trace points)
resume	Resume ALL tracing (except for threads suspended by the action of ibm.dg.trc.resumecount property and Trace.suspendThis() calls)
suspendthis	Increment the suspend count for this thread. A non-zero suspend count prevents all tracing for the thread.
resumethis	Decrement the suspend count for this thread if it is greater than zero. If the suspend count reaches zero, tracing for this thread will be resumed
coredump	Produce a coredump
javadump	Produce a javadump
heapdump	Produce a heapdump
snap	Snap all active trace buffers to a file in the current working directory. The name of the file is in the format Snapnnnn.yyyymmdd.hhmmssth.ppppp.trc where nnnn is the sequence number of the snap file since JVM startup, yyyymmdd is the date, hhmmssth is the time, and ppppp is the process id in decimal with leading zeroes removed.

For example:

• Start tracing this thread when it enters any method in java/lang/String and stop tracing when it leaves it.
  
  -Dibm.dg.resumecount=1
-Dibm.dg.trc.trigger=method(java/lang/String.*,resumethis,suspendthis)
  
  
• Resume all tracing when any thread enters a method in any class beginning with "error" .
  
  -Dibm.dg.trc.trigger=method(*.error*,resume)