Home

JPROF - Java Profiler

General Information:: Overview; Quick Start
Using JPROF:: Invocation Options; Metric Selection Options; Runtime Control; Controlling Java Compilation; Record and Playback (Windows only)
Additional Information:: Files Produced by JPROF

Overview

jprof.dll

libjprof.so

libjprof.a

tinstall

Common usages of JPROF are:

Resolving JIT Addresses to Names (jita2n) to support TPROF and ITRACE post processing.

Capturing execution flow in the form of call trees (calltree or scs), which may also include information about object allocations or monitor usage for each node in the tree.

Capturing the state of the Java Heap that can later be post processed by HDUMP.

Capturing information about JVM usage of locks via the Java Lock Monitor (JLM).

JPROF functions are controlled by Java Invocation Parameters and by RTDRIVER commands from a command line or from Java.

JPROF causes significant application slowdown due to additional execution pathlength in the JVM, JIT, and JPROF due to instrumentation, the overhead associated with generating and handling the events used while profiling the application. This can be on the order of 1.5 to 10 times the original pathlength.

JPROF compensates for this overhead via "calibration", an automated process of calculating the amount of time spent performing the instrumentation, then removing that amount from all statistics reported about the functions that have been instrumented. Without calibration, it is often impossible to accurately determine the significance of small routines because they are overwhelmed by the instrumentation that has been inserted to measure them.

Please note that even with calibration, this instrumentation overhead may cause unexpected changes in your application. For example, increased pathlength can change cache behavior, wait times, and the behavior of background tasks.

Accuracy of calibration is achieved through the use of metrics, such as the number of instructions completed between events. The Per Thread Time (PTT) facility consists of kernel code that manages hardware counters to correctly assign metrics, such as time or instruction completed, to each thread. The availability of metrics, and even PTT, varies by platform.

When PTT is available, the number of instructions completed allows accurate calibration because null routines can be profiled to determine the minimum overhead associated with various events. When PTT is not available or not used, the metric is defaulted to elapsed machine cycles and the calibration may be much less accurate. See Calibration for a detailed description of how this calibration is performed.

The tracking of object allocations, the numbers of Allocated Objects (AO), Allocated Bytes (AB), Live Objects (LO), and Live Bytes (LB), does not need calibration, since these values are not changed by instrumentation.

Quick Start

A few quick examples of how to use JPROF are listed below:

To resolve JIT Addresses to Names for TPROF (with run.tprof) using JVMPI use:
or for JVMTI use:
This data is post-processed using:
together with swtrace.nrm2, to produce tprof.out.

To capture execution flow in the form of call trees using JVMPI use:
or for JVMTI use:

To capture object allocations in the call tree using JVMPI use:
or for JVMTI use:

To record all of the callflow and object allocation events for later playback for JVMPI use:
or for JVMTI use:
To playback the results with JVMPI use:
or with JVMTI use:
Where 'pid' is the process id of java when the recording was made.

To capture execution flow in the generic format using instruction completed on thread as the metric for JVMPI use:
or for JVMTI use:
To use cycles on thread as the metric use:

Invocation Options

-Xrunjprof:

-agentlib:jprof=

Additional options can be appended to this list by using the JPROFOPTS environment variable. This environment variable makes it easy to temporarily add options to JPROF without having to modify existing scripts.

Because many WebSphere® applications use multiple JVMs, environment variables generally do not work because they only apply to the initial JVM. Instead, the JPROF options need to be added to server.xml, the Websphere Application Server configuration file, to guarantee that JPROF is attached to the correct JVM. It is good practice to save/back up the original version before modifying it. One way to update the server.xml is to use a browser to access the WebSphere Administrative Console and follow these steps:
-> Go to the WebSphere Administrative Console -> Servers -> Application Servers -> select server
-> Go to "Java and Process Management" -> Process Definition -> Java Virtual Machine
-> Go to the "Generic JVM Arguments" and enter the appropriate jprof options in the box.
-> click OK and -> save.
Note the options in the "Generic JVM Arguments" box are put on the JVMs command line for the server.

The parameter parser supports up to five ways to specify each option. For example, pidx, the option that adds the process id as a suffix to all file names, can be specified as pidx, +pidx, allpidx, -pidx, or nopidx. "all" is an alias for "+" and "no" is an alias for "-" to make the options as readable as possible.

Many options also have aliases, such as enableheapdump and its alias, ehd.

The most important two options are help and allhelp, since they are used to display the help information built into JPROF itself. help displays information about only the most commonly used options. allhelp displays information about all options, including debugging options and those that may be obsolete or are deprecated.

Since the help information is integrated into the option parser, the help and allhelp options produce the most up-to-date documentation available for JPROF. Follow this link to view the standard help listing in its current form.

Metric Selection Options

When you specify callflow mode, you automatically get per thread instructions and per thread cycles as your metrics. If you do not want to use any metrics, which is commonly done when you are only interested in profiling memory usage or if you are not using our device driver, you can select calltree mode.

There are three kinds of metrics: physical, logical, and composite. Physical metrics define what data is gathered, while logical metrics define what data is displayed. Composite metrics are logical metrics which depend on multiple physical metrics.

All of the metrics that you specify are treated as logical metrics. That is, they will produce a column of output in the log-rt files. The physical metrics are implicitly specified by the set of logical metrics. The only times that this distinction is important is when you are doing metric scaling or using the record and playback modes.

ptt_insts: Selects instructions completed on the thread as a physical metric. This is the default when generic or gencalib is specified
ptt_cycles: Selects cycles executed on the thread as a physical metric.
raw_cycles: Selects cycles executed on any thread as a physical metric. This is sometimes known as wallclock time. This metric is always implicitly selected to support timestamps, unless nometrics is specified.
lat_cycles: Selects latency cycles, raw_cycles minus ptt_cycles, as a composite metric. This metric is only non-zero when cycles were executed on another thread, implying latency. If ptt_cycles has not already been specified, it will be added to the list of physical metrics.
cpi: Selects cycles per instruction, ptt_cycles divided by ptt_instr, as a composite metric. If ptt_insts and ptt_cycles have not already been specified, they will be added to the list of physical metrics.
nometrics: Selects a special metric that does not reference any physical metrics. This metric is simply a count of metric references on the thread and can be used to support basic call flow analysis in situations where physical metrics can not be used, like SMP systems where no device driver is installed.

Default metrics can be overridden using the metrics=metricname option, using any of the metric names above. Multiple metrics can be specified using a '+' between them. For example, metrics=ptt_insts+ptt_cycles is the default when callflow is specified.

All metrics can use :n as a suffix to shift out the last n decimal digits. All metrics ending with _cycles can be scaled to seconds, milliseconds, microseconds, or nanoseconds using :sec, :msec, :usec, or :nsec. You can add logical metrics using the metrics= option. For example, metrics=ptt_cycles+ptt_cycles:nsec will produce two columns of cycles on thread, first unscaled, then scaled to nanoseconds.

As another example, metrics=ptt_insts+ptt_cycles+cpi will produce the standard callflow output with an additional column for CPI. However, composite metrics, such as CPI, have no delta columns in log-rt.

Runtime Control

JPROF can be controlled at runtime via either RTDRIVER commands from a command line or RTDRIVER methods from Java.

RTDRIVER commands from a command line

General
RTDRIVER is a socket-based command-line application that connects to JPROF to allow starting and stopping of tracing at runtime. This allows large, long running applications to run at full speed until they arrive at the point where you wish to analyze them.

Starting RTDRIVER
RTDRIVER is a client-side socket connection. Since JPROF always opens a socket connection for commands, RTDRIVER connects to JPROF and presents the user with a command line. The simplest case with client and server on the same machine is shown below:
1. rtdriver -l (local machine as host)
2. When RTDRIVER connects to the host socket a command prompt will appear. The list of supported interactive commands is shown below. RTDRIVER supports some abbreviations for convenience. See rtdriver-usage (interactive commands).

Rtdriver Commands
Rtdriver commands supported in jprof are listed below. These commands can be issued via the rtdriver application or the RtDriver.class.
Multiple commands can be separated by commas, such as fgc,hd to force garbage collection and immediately perform a heapdump.

start[=n]
Begins collecting data. Optional n second delay.

end
This is a more controlled form of flush, followed by reset, which waits for all pending events to complete before executing the flush, then performs the reset.

flush
Produces a log-rt file as a snapshot of the data collected, without performing a reset.

reset
Total reset of jprof data. You must use a start command to begin collecting data again.

shutdown
Produces a final log-rt file, if data collection is active, then kills the process.

fgc
Force Garbage Collection.

fgcf
Force Garbage Collection and Flush

jlmstart[=n]
Start Java Lock Monitor with hold time accounting. Optional n sec delay.

jlmstartlite[=n]
Start Java Lock Monitor hold without time accounting. Optional n sec delay.

jlmreset
Stop Java Lock Monitor and restart in previous mode (default to time)

jlmdump
Request Java Lock Monitor dump (creates log-jlm.n_pid file)

jlmstop
Stop Java Lock Monitoring

hd
request a detailed heap dump (log-hd.n_pid and log-hdcnm.n_pid files)

hds
request a heap class summary only (log-hdcnm.n_pid file)

hdf
same as hd + flush

thread_dump
Signal for a java coredump (includes thread stack dump)

RTDRIVER methods from Java

The RtDriver.command method allows you to send any valid RTDRIVER command to the copy of JPROF that was loaded by your JVM.

public static void command(String cmd)

To send the start command, followed by the hd command, simply add these statements to your java program:

import jperf.RtDriver;

RtDriver.command("start");

RtDriver.command("hd");

Some command abbreviations are implemented only in RTDRIVER and not in RtDriver.class. Over time, these abbreviations will be moved to JPROF and eliminated from RTDRIVER, making both command sets the same.

Controlling Java Compilation

It is sometimes necessary to control the compilation of Java methods to properly profile your applications. For example, the inlining of small methods can make them disappear from reports because they no longer generate entry and exit events once they have been compiled. This section explains how to control the compilation.

IBM SOV JVM
- Compiling control. The java JIT compiler compiles methods based on a variety of criteria. One criteria is the number of times the method has been called. To control this feature use the following environment variable :
  This will cause "jitting" after n calls.
- Inlining control. By default the java JIT compiler will at times inline methods in order to increase performance. For code flow analysis it may by useful to disable that function. The following JAVA environment variable does this :
IBM J9 JVM
- Compiling is controlled by the count= JIT option, as shown below:
  This will cause "jitting" after n calls.
- Inlining is controlled by the disableInlining JIT option, as shown below:
- You specify -Xjit:options as a command line parameter when invoking Java. For example, to specify both of these options when executing your classfile, you could invoke Java with the following commmand:

Record and Playback Modes (Windows only)

When applications use most of available memory, the memory required to build callflow trees can significantly impact the application. To address this problem, we have created the record and playback modes.

During record mode, all events are recorded by writing them to log-trace. By default, no trees are built during record mode, so that there is almost no impact on application memory. To reduce the execution impact, the instrumentation used to capture the events only writes the information to a buffer and a separate thread performs the actual writing to disk. No other processing is performed at record time, unless the trees option is specified.

During playback mode, all of the events are read from log-trace and normal processing is performed. Since memory is no longer shared with the application, the trees can be much bigger than before. Gathering of calibration data is performed only on the first reading of the log-trace file and stored in log-trace-calib to speed up later processing of the same file.

All of the names of the output files have a 'p' appended to them. That is, log-msg becomes log-msgp and log-rt.1 becomes log-rtp.1. The headers of these playback files reflect the information at record time, not playback time, since playback can even be performed on a different JVM or operating system.

There are many additional advantages to playback mode, not the least of which is selective playback. That is, the data can be filtered at playback time to produce files that reflect activity only of specific methods and/or threads during specific time intervals. Any subset or combination of the physical metrics that were recorded can be specified as logical metrics at playback time.

To use record mode, simply include record among the specified options. To use playback mode, you execute java again with playback as the first JPROF option. You do not need to specify a classfile, since java is only used as scaffolding to load JPROF.

All of the options specified at playback time are appended to the options that were specified at record time. These merged options are the only differences that you should see in the file headers between the record and playback versions of the output files when the trees option is used at record time.

Since all JPROF options are processed from left to right, debug options and any options that are meaningless at playback time, like heapdump, are automatically reset when the playback option is parsed. Therefore, verbose or verbmsg must be specifed after the playback option if you wish to see verbose messages at playback time.

Metrics specified after the playback option are logical metrics that define the columns that will appear in the log-rtp files. Only metrics which use the physical metrics that were recorded can be specified. If generic or gencalib is specified, the first of these logical metrics will be used for the log-genp files.

Files Produced by JPROF

JPROF can generate a variety of files, based on the options that are specified. By default, all of the files are placed in the current directory and use "log" as a prefix, such as log-msg.

The logpath=path option can be used to select a different directory, while the logprefix=prefix option will change the prefix used to create the filenames. For example, if logpath=abc,logprefix=def is specified, then log-msg would be replaced by abc/def-msg.

Unless you specify nopidx, all of the files will use a _PID extension, such as log-msg_1234 for process 1234.

The types of files produced by JPROF and their contents are:

log-msg: All messages generated by JPROF. This is always produced.
log-rt: The call tree of methods and their associated data. This is produced in calltree or scs mode in response to a flush or end command from RTDRIVER or when the JVM terminates while profiling is still active.
log-gen: The call tree of methods in generic form. This is produced in generic mode.
log-hd: The raw data from a heapdump. This is produced in response to a heapdump command from RTDRIVER or at JVM termination when the hd option is used with JVMTI. The ehd or enableheapdump option must be specified, unless hd was specified. This file is post-processed by HDUMP.
log-hdcnm: A summary of the heapdump by class name. This is produced whenever any heapdump command is received or at JVM termination when the hd option is used with JVMTI.
log-jita2n: Address-to-Name translations for all Jitted methods, plus bytes of instructions if the jinsts option is specified. This is produced in tprof and itrace modes or when jita2n is specified. This file is used by post when post-processing .nrm2 files and other trace files.
log-jitinfo: JIT related output. This is produced in tprof and itrace modes when the jitinfo option is specified.
log-jtnm: Thread start and stop information, by name. This is produced in tprof and itrace modes or when the threadinfo option is specified.
log-jinsight: JINSIGHT related output. This is produced only in jinsight mode.
log-out: Various internal debugging information. This is produced only in output mode.

Home