Contents

Introduction

Installation

Basic Recording and Visualization

Recording Scheduling Events

Synchronized Recording
Dynamic Recording

Visualizing Scheduling Events

Per-Thread View

Zooming-in
Thread Information
Color Schemes
Measuring Time Intervals
User Events

Per-CPU View

Zooming-in
Color Schemes

Summary View
TSV and 64-bit VM

Advanced Recording and Visualization

Using Custom Scripts for Synchronized Recording
Using Custom Scripts for Dynamic Recording
Log File Format
User Events
Asynchronous User Events
Call Stacks

Log File Management

Log File Information
Log File Searching
Log File Splitting and Filtering

Contact Us

Introduction

Thread scheduling is an important aspect of real-time programming. However, it is often difficult to obtain an exact vision of the real scheduling of a multi-threaded application. The Thread Scheduling Visualizer (TSV) is a set of tools that provide an easy way to record and visualize thread scheduling for the Sun Java™ Real-Time System (Java RTS). This tool set includes customizable DTrace scripts to record the scheduling events, as well as a visualizer to provide a graphical view of the events.

Installation

The Thread Scheduling Visualizer can be installed anywhere. Once it is installed, ensure that your PATH variable contains the bin directory of your installation of the TSV.

The installation includes several utilities and DTrace scripts.

Dependencies are as follows: Korn shell; the commands sort, java, dtrace, and (optionally) c++filt.

Basic Recording and Visualization

The recording and visualization of the scheduling events are always performed in two steps. The recording is performed using DTrace scripts during application execution, and the data it produces is stored in a log file. Once the log file has been generated, the TSV visualizer utility reads it and displays the contents with a graphical UI.

Recording Scheduling Events

There are two ways to generate a log file: with synchronized recording and with dynamic recording. The first one performs a synchronization between the recording script and the virtual machine at the beginning of its execution, so it's useful for recording a full execution including the start-up phase. The second one can be used at any time to monitor a running application over a specified period.

Synchronized Recording

To perform a synchronized recording, all the selected DTrace probes must be activated before the VM starts its initialization. This task is handled by the scripts provided with TSV. These scripts use a special VM option to pause the VM process just after the loading of the libjvm.so library and before the beginning of the VM initialization. Once the VM is paused, these scripts launch a DTrace script, which activates all the probes it needs and then resumes the VM process.

The drecord (Default RECORDing) script is the simplest tool for performing a synchronized recording of your application. This script uses a default set of DTrace probes to monitor the VM and the application.

To activate the recording of scheduling events, launch your application with the drecord command added in front of your usual command line.

$ /opt/SUNWrtjv/bin/java YourApplication arg1 arg2

To generate the log file with TSV, use the following command:

$ drecord /opt/SUNWrtjv/bin/java YourApplication arg1 arg2

The first argument passed to drecord must be the VM invocation command. The script automatically adds the -XX:+PauseAtStartup option immediately after this first argument to perform the synchronization between the VM and the DTrace script.

More advanced synchronized recording techniques are described here.

Dynamic Recording

Dynamic recording can be used at any time on a running Virtual Machine. It doesn't require a synchronization as the one performed by the synchronized recording scripts. However, once the events have been recorded by the DTrace script, a thread dump is performed in order to get the name of the different threads. The thread names are collected through DTrace probes but the output from the thread dump appears on the standard output of the VM.

The dmonitor (Default MONITORing) script is the simplest tool for performing a dynamic recording of your application. This script uses a default set of DTrace probes to log scheduling events.

In order to activate a dynamic recording you first need the PID (Process ID) of the Java Virtual Machine. The PIDs of running VMs can easily be obtained with the jps command:

$ jps
24420 Jps
16649 MyApplication

With this example, the VM has the PID 16649. The dmonitor utility takes a second argument which is the time, in second, of the recording. For instance, to monitor the Java application 'MyApplication' for 30 seconds, just type:

$ dmonitor 16649 30

More advanced dynamic recording techniques are described here.

Visualizing Scheduling Events

Once the recording script has completed its task, it prints a message providing the name of files generated in the current directory, for instance:

Log generated in file log22325.jrt3
Per-CPU view generated in file cpu22325.jrt3
Summary generated in file summary22325.txt

TSV provides several ways to visualize the data stored in the log file. Depending of the application and the issues being investigated, some views are more adapted than the other. The three provided views are:

• A per-thread view

• A per-CPU view

• A summary view

Per-Thread View

To get a per-thread visualization of the recorded execution, launch the Thread Scheduling Visualizer with the first log file name as argument:

tsv log22325.jrt3

The TSV application starts and displays a window as shown below:

The display window is divided into three output areas:

• At the top of the display, the thread scheduling is represented using a timeline scheme. Each line is dedicated to a thread. The time is represented from left to right (oldest timestamps on the left). When a thread is running, a colored box is displayed on its timeline; when it is not running, no box is printed.

• At the bottom left is the system message area, where the tool writes messages concerning its execution.

• The bottom right area contains a set of text fields that contain information about a particular thread.

Zooming-in

Before zooming, note that the "Zoom factor" is initialized to 1, and the zoom slider is completely to the left of the display.

To zoom in on a particular part of the displayed scheduling, move the mouse cursor to the beginning of the area you want to zoom in, press the left button, drag the mouse cursor to the end of the area you want to zoom in, and release the left button. Notice, as in the display below, that the time resolution is larger, the zoom factor has increased, and the zoom slider has moved to the right.

Now we zoom in again to obtain the display shown below.

To zoom out, just move the zoom slider to the left.

Thread Information

To obtain information about a thread, move the mouse cursor over one of the colored boxes. The information relative to this thread is displayed in the text areas in the bottom right part of the TSV window. The Thread ID field contains the user and the kernel thread ID. The Thread Name text area contains the thread name. If the thread does not have a name yet, a default name is printed, composed of the word "Unnamed Thread" followed by a white space and the thread number. The Thread Priority field contains the thread's effective priority. The Scheduling Class shows which scheduling algorithm is used for the execution of this thread. The CPU ID text area contains the ID of the CPU on which the thread is running. The Timestamp shows the timestamp of the recorded event used to display the box being observed; it can be used to quickly find a particular sequence of events directly in the log file.

The figure below shows information for a thread.

Color Schemes

TSV supports several color schemes. Each color scheme aims to highlight some aspects of the scheduling. The color scheme used by TSV can be selected with the combo box above the message area.

By default, the TSV uses a color scheme called "Set by priorities," in which the boxes corresponding to thread execution are colored according to their current priority. Three colors represent the three sets of scheduling classes:

• Green: Time Sharing/Interactive/Fair Scheduling
• Blue: System
• Red: Real-Time

In each scheduling class, the lighter the color, the higher the priority. The boxes representing user events are not colored according to the thread's priority, but are colored randomly. If user events are not visible enough, it is possible to generate a new set of random colors by clicking on the "Randomizer" button.

Another useful color scheme is "Set by CPU", in which the color of a running thread depends on the CPU it is running on. With this color scheme, it is very easy to detect when a thread migrates from one CPU to another.

The figure below shows an example of CPU based coloring. Threads are displayed in blue when running on CPU 0 and red when running on CPU 1.

Measuring Time Intervals

Measuring time intervals is very simple. By left-clicking in a timeline area, you create a bookmark. By left-clicking on another location in the timeline area, you create a second bookmark, and the difference of time between the two bookmarks is printed in the system message area (at the bottom left), as highlighted in the display below.

User Events

User events are represented as small boxes on top on the regular boxes representing a thread's execution. Moving the mouse cursor over one of these boxes causes a pop-up window to appear with the user-event message. This user-event message is also printed in the Message text area (at the bottom right), as highlighted in the display below. The other fields display information relative to the thread that fired this user event.

Per-CPU View

In some cases, the per-thread view doesn't allow you to easily see the correlation between different events. This is often the case when the log file contains a huge number of threads or when investigated events involve a lot of threads. In these cases, the per-CPU view can make event relationships more evident.

For a per-CPU view, the original log file has to be processed in order to rearrange the data it contains. A per-CPU view file is automatically generated by the [cd]record and [cd]monitor utilities. It is also possible to manually generate a per-CPU view file with the thr2cpu utility. To generate the per-CPU view for log file log22506.jrt3, just type:

$ thr2cpu log22506.jrt3 > cpu22506.jrt3

The size of a processed log file is significantly bigger than the original log file. When working with huge log files, be sure to have enough disk space.

Once the processed log file has been generated, open it with the Thread Scheduling Visualizer using the tsv command:

$ tsv cpu22506.jrt3

The Thread Scheduling Visualizer shows up but this time, each time line represents a CPU instead of a thread. In the figure below, only two time lines are displayed, showing that the application ran on a two-CPU machine.

Zooming in

By zooming in, you can see more clearly the time slots in which each CPU run the application.

Color Schemes

By default, TSV starts with the priority-based coloring scheme, but this makes it difficult to track the execution of a given thread. By selecting the "Set by Thread ID" coloring scheme, one color is assigned to each thread, making thread identification much easier.

Sometimes, two different threads have close colors, making them difficult to differenciate. By clicking on the "Randomizer" button, all colors are reassigned randomly, hopefully assigning more differenciable colors for the previous threads.

Summary View

The graphical representation of the execution helps in many cases, but it cannot provide quantitative data about migrations or contentions. A summary file is automatically generated by the [cd]record and [cd]monitorsummarize utility.

To generate a summary file from a log file just type:

$ summarize logfile.jrt3 > summary.txt

Here's an example of content from a summary file:

$ less summary.txt
First timestamp: 2854488769472443 Last timestamp: 2854518711265452
Total elapsed time: 29sec 941ms 793us 9ns 
Number of thread: 51

Thread 2 : DestroyJavaVM
	priority range: 0 - 0
	CPU time: 0 ns = 0ns  ( 0 % )
	Migrations count: 0 / Mean Migration Interval: 0
	CPU utilization:
	Locks contentions:

Thread 3 : GCtaskthread#0(ParallelGC)
	priority range: 49 - 60
	CPU time: 16822078 ns = 16ms 822us 78ns  ( 0 % )
	Migrations count: 12 / Mean Migration Interval: 727ms 694us 488ns 
	CPU utilization:
		CPU 0 : 12915202 ns = 12ms 915us 202ns  ( 76 % )
		CPU 1 : 3906876 ns = 3ms 906us 876ns  ( 23 % )
	Locks contentions:

Thread 4 : GCtaskthread#1(ParallelGC)
	priority range: 59 - 60
	CPU time: 17127546 ns = 17ms 127us 546ns  ( 0 % )
	Migrations count: 18 / Mean Migration Interval: 1sec 142ms 308us 761ns 
	CPU utilization:
		CPU 0 : 4008197 ns = 4ms 8us 197ns  ( 23 % )
		CPU 1 : 13119349 ns = 13ms 119us 349ns  ( 76 % )
	Locks contentions:

Thread 5 : VMThread
	priority range: 29 - 59
	CPU time: 1315396021 ns = 1sec 315ms 396us 21ns  ( 4 % )
	Migrations count: 78 / Mean Migration Interval: 103ms 282us 693ns 
	CPU utilization:
		CPU 0 : 571382928 ns = 571ms 382us 928ns  ( 43 % )
		CPU 1 : 744013093 ns = 744ms 13us 93ns  ( 56 % )
	Locks contentions:

Thread 29 : Rotator3D Demo
	priority range: 34 - 59
	CPU time: 4025256 ns = 4ms 25us 256ns  ( 0 % )
	Migrations count: 27 / Mean Migration Interval: 27ms 290us 922ns 
	CPU utilization:
		CPU 0 : 874782 ns = 874us 782ns  ( 21 % )
		CPU 1 : 3150474 ns = 3ms 150us 474ns  ( 78 % )
	Locks contentions:
		java/util/HashMap
			contentions: 1
			max blocked time: 898378 ns = 898us 378ns 
			cumulated blocked time: 898378 ns = 898us 378ns 
		javax/swing/RepaintManager
			contentions: 1
			max blocked time: 829176 ns = 829us 176ns 
			cumulated blocked time: 829176 ns = 829us 176ns 

Thread 28 : Intersection Demo
	priority range: 34 - 59
	CPU time: 4528780 ns = 4ms 528us 780ns  ( 0 % )
	Migrations count: 28 / Mean Migration Interval: 25ms 651us 629ns 
	CPU utilization:
		CPU 0 : 3910211 ns = 3ms 910us 211ns  ( 86 % )
		CPU 1 : 618569 ns = 618us 569ns  ( 13 % )
	Locks contentions:
		javax/swing/RepaintManager
			contentions: 2
			max blocked time: 857826 ns = 857us 826ns 
			cumulated blocked time: 1697356 ns = 1ms 697us 356ns 

TSV and 64-bit VM

Generated log files are sometime huge and complex, especially when they cover a long period of time or a huge number of threads. Displaying these huge log files requires a lot of memory, and in some cases, the use of a 64-bit VM is required. To launch the Thread Scheduling Visualizer in a 64-bit VM, set the JAVA_HOME environment variable to point to the root directory of a 64-bit JVM, and launch TSV using the tsv64 utility:

$ tsv64 hugelog.jrt3

Advanced Recording and Visualization

We have seen that the drecord and dmonitor utilities use a default set of DTrace probes to log scheduling events. But it is possible, and sometimes recommended, to use customized scripts to focus recording on important aspects of the application or to highlight particular events.

Using Custom Scripts for Synchronized Recording

The crecord (Custom RECORDing) utility eases the recording of scheduling events by using customized scripts. The utility takes as argument the DTrace script to be used to record events, followed by the command line to launch the application.

For instance, to record an execution using the default script, type the following:

$ crecord default.d /opt/SUNWrtjv/bin/java YourApplication arg1 arg2

The DTrace script argument can be a direct path to a custom script, or just the name of one of the scripts in the dscripts directory of your TSV installation.

The DTrace script used to log scheduling events must generate a log file with the format recognized by the TSV visualizer. This format is described in the "Log File Format" section.

Using Custom Scripts for Dynamic Recording

The cmonitor (Custom MONITORing) utility eases the recording of scheduling events by using customized scripts. The utility takes as argument the DTrace script to be used to record events, followed by the process ID of the Virtual Machine and the duration of the recording in seconds.

For instance, to record an execution using the default script, type the following:

$ cmonitor default.d 12645 30

The DTrace script argument can be a direct path to a custom script, or just the name of one of the scripts in the dscripts directory of your TSV installation.

The DTrace script used to log scheduling events must generate a log file with the format recognized by the TSV visualizer. This format is described in the "Log File Format" section.

Log File Format

The log file must have one record per line (empty lines are ignored), and each record must match one of the following formats. The fields must be separated by white spaces. All the lines begin with a timestamp, and the log file must be in order by increasing timestamp.

Timestamp	Command	Arg1	Arg2	Arg3	Arg4
Timestamp	"cpu-view"
Timestamp	"on-cpu"	Thread ID	CPU	Priority
Timestamp	"off-cpu"	Thread ID
Timestamp	"set-name"	Thread ID	Thread name ...
Timestamp	"user-event"	Thread ID	CPU	Priority	Message ...
Timestamp	"async-begin"	Thread ID	CPU	Priority	Message ...
Timestamp	"async-end"	Thread ID	CPU	Priority	Message ...
Timestamp	"call-stack"	counter	Thread ID	CPU	Priority
Timestamp	"call-stack"	counter	Frame ...
Timestamp	"call-stack-end"

In this table, when an argument ends with three dots it means that all the remaining content of the line is processed to build this last argument.

User Events

It is easy to customize a DTrace script to add new user events in order to get more information specific to the application being monitored. Here's a example on how to print a message for a specific event:

jrts$target:::monitor-wait
{
  printf("%d user-event %d %d %d Starting wait() on a monitor\n",timestamp,tid,cpu,curthread->t_pri);
}

This code generates a user event with the message "Starting wait() on a monitor" every time a thread calls wait(). It might be useful to have also the class of the instance used to call wait(). Let's improve the code:

jrts$target:::monitor-wait
{
  printf("%d user-event %d %d %d Starting wait() on %s\n",timestamp,tid,cpu,curthread->t_pri,
         copyinstr(arg1,arg2));
}

Now, the message prints the class name. By default, the pop-up window displaying the user event message uses a single line. For some complex messages, it's sometime better to split the message into several lines. This can be done by adding a \n (the backslash character followed by the 'n' character) sequence in the message string. For instance:

jrts$target:::monitor-wait
{
  printf("%d user-event %d %d %d Starting wait() on \\n%s\n",timestamp,tid,cpu,curthread->t_pri,
         copyinstr(arg1,arg2));
}

Asynchronous User Events

The visualizer shows the application's execution in a thread-based way, but it is sometimes useful to display information that is not linked to a particular thread. For this purpose, TSV supports a particular type of event called "Asynchronous User Events." All events of this type are displayed in the same timeline, and this timeline is not associated with a particular thread. By default, this timeline is at the bottom of the timeline display. In addition, as explained in Color Schemes, you can change the color for the user events with the "Randomizer" buttom.

Asynchronous user events are handled using the async-begin and async-end line format. The visualizer tries to match async-begin and async-end events using their message string.

Even if the asynchronous user events are not directly associated with a particular thread, some thread information is displayed when the mouse cursor is moved over one such event in the timeline area. This information concerns the thread that generated the async-begin event in the log file. There is currently no way to display information about the thread that generated the async-end event.

The first example uses asynchronous user events to display blocked time on monitor contention. Here is the DTrace code used to generate the event entries in the log:

jrts$target:::monitor-contended-enter
{
    printf("%d async-begin %d %d %d Blocked on contended lock %s@%p\n", 
       timestamp,tid,cpu,curthread->t_pri,copyinstr(arg1,arg2),arg0);
}

jrts$target:::monitor-contended-entered
{
    printf("%d async-end %d %d %d Blocked on contended lock %s@%p\n", 
       timestamp,tid,cpu,curthread->t_pri,copyinstr(arg1,arg2),arg0);
}

Here is the output on the visualizer. Note that the Thread ID text field contains asynchronous event (0).

The second example uses asynchronous user events to display GC cycles. Here is the DTrace code used to generate the event entries in the log:

jrts$target:::rtgc-cycle-begin
{
    printf("%d async-begin %d %d %d RTGC Cycle\n", 
       timestamp,tid,cpu,curthread->t_pri);
}

jrts$target:::rtgc-cycle-end
{
    printf("%d async-end %d %d %d RTGC Cycle\n", 
       timestamp,tid,cpu,curthread->t_pri);
}

Here is the output on the visualizer:

Call Stacks

DTrace provides an easy way to display the Java call stack with its built-in function jstack(). It is sometimes very helpful to display these call stacks at a particular point in the application's execution. But the output of the jstack() function is not flexible and does not meet the requirements of the log file format. However, the [cd]record and [cd]monitor scripts include a post-processing to convert jstack() output into well-formatted call-stack and call-stack-end events. In order to obtain more easily readable call stacks, it is recommended to make the c++filt utility accessible through the PATH environment variable. If c++filt is available, scripts automatically use it to demangle symbol names.

In the visualizer, the call stacks are displayed as small boxes on top on the regular boxes representing a thread's execution, like the user-events. Moving the mouse cursor over one of these boxes causes a pop-up window to appear with the whole stack trace of the thread at this particular moment, as highlighted below. It is possible to select text within the pop-up window to copy it into another application.

For instance, here is the code to print call stacks whenever a thread blocks on a contended monitor:

jrts$target:::monitor-contended-enter
{
    printf("%d call-stack 0 %d %d %d\n", 
       timestamp,tid,cpu,curthread->t_pri);
    jstack();
}

And here is the output it produces in the visualizer:

Log File Management

Once generated, a log file can be examined and manipulated using the logfilt utility. By default, logfilt prints a message every 100,000 records it processes. To disable it, add the -q option on its command line.

Log File Information

The -l option provides the following information about a log file: first and last timestamp, the duration of the recording, the number of threads, and the thread list.

% logfilt -q -l example/log2.jrt3
Number of records     : 9862420
Filtered out records  : 9862419
First timestamp       : 3443858417570764
Last timestamp        : 3444721362739274
Duration              : 0 h 14 mn 22 s 945 ms 168 us 510 ns
Number of threads     : 25
Threads list          : {3=Gang worker#1 (RTGC Threads), 14=WatcherThread, 
                         17=Thread-1, 6=RTGC Thread#0, 1=main,
			 5=Gang worker#3 (RTGC Threads), 
                         16=Thread-0, 24=RealtimeServerThread, 
			 11=SignalThread,  15=DeadlineMonitoringThread,
			 4=Gang worker#2 (RTGC Threads), 
			 23=RealtimeServerThread, 12=CompilerThread0, 
                         7=VMThread, 18=RealtimeThread-0, 
			 2=Gang worker#0 (RTGC Threads), 
                         20=HighResTimerThread, 
			 25=NoHeapRealtimeServerThread-22, 
                         21=NoHeapRealtimeServerThread, 
			 10=SurrogateLockerThread, 
                         13=LowMemoryDetectorThread, 
			 22=NoHeapRealtimeServerThread, 
                         9=Finalizer, 19=NoHeapRealtimeThread-0, 
			 8=Reference Handler}

Log File Searching

The logfilt utility has also a search capability to find occurrences of user events in a log file. The search request takes a string as argument, and prints information about all user events which have this string as part of their own string message. The output includes the occurrence time relative to the beginning of the record, the name of the thread which generated this user event, and the full message of the user event.

Here is an example to search for a particular user event with the string message "Msg 1":

% logfilt -s "Msg 1" log1.jrt3
0 h 0 mn 13 s 553 ms 168 us 120 ns in thread main : Msg 1 

Here is a second example with a request to find all user events having "Msg" as part of their own message:

% logfilt -s Msg log1.jrt3
0 h 0 mn 13 s 553 ms 168 us 120 ns in thread main : Msg 1
0 h 0 mn 15 s 562 ms 4 us 706 ns in thread main : Msg 2

Log File Splitting and Filtering

Sometimes the log file generated is too big to be displayed with the graphical interface. One way to handle this situation is to split the log file into several smaller log files according to time parameters. The logfilt utility can create a subfile while preserving all the information required by the graphical interface to identify each thread. You can run this utility as many times as necessary to create the desired subfiles from the original log file.

The logfilt utility can optionally use any one of three different types of time parameters to split a log file: timestamp, elapsed time, or user event. You can specify a start parameter, or an end parameter, or both, but they are not mandatory. The default start parameter is the beginning of the log file, and the default end parameter is the end of the log file. However, it is not possible to mix parameter types, for instance, you cannot specify a start parameter using timestamp and an end parameter using user events.

The parameters are specified as follows:

• -tsbegin <long> : specify a start parameter using a timestamp
• -tsend <long> : specify an end parameter using a timestamp
• -hrbegin <[HH:]MM:SS> : specify a start parameter using elapsed time
• -hrend <[HH:]MM:SS> : specify an end parameter using elapsed time
• -evbegin <string> : specify a start parameter using a user event
• -evend <string> : specify an end parameter using a user event

It is also possible to use logfilt to filter a log file according to priority criteria. When you specify a priority range, logfilt generates a new log file containing scheduling information only for threads that have run within this priority range, removing all data related to threads that never executed in this priority range.

The priority range is specified as follows:

• -pmin <int> : specify the minimum priority (default is the lowest priority of the system)
• -pmax <int> : specify the maximum priority (default is the highest priority of the system)

Note: priority values are Solaris global priorities. For instance, the lowest real-time priority in Java RTS has value 11 but it is mapped on Solaris global priority 100. To remove all threads that never run within the real-time priority range, the command line looks like this one:

% logfilt -pmin 100 loginitial.jrt3 > logfiltered.jrt3

Another filtering mode supported by logfilt is based on thread names. It is possible to select or exclude threads from a log file according to name patterns. The patterns have to be written according to the java.util.regex package.

The parameters of thread-name-based filtering are specified as follows:

• -select <pattern> : specify a pattern of thread name to select
• -exclude <pattern> : specify a pattern of thread name to exclude

The -select and -exclude filtering operations are mutually exclusive. However, it is possible to specify several select or exclude patterns on a single command line.

Example:

To select only threads with a name starting with "RealtimeThread":

% logfilt -select "RealtimeThread.*" loginitial.jrt3 > logfinal.jrt3

If a filename is specified on the logfilt command line, the program will use this file as the source log file. Otherwise, it will wait for the name of the source log file on its standard input stream.

By default, logfilt generates the new log file on the standard output. The new log file can be generated directly into a file using the -o option followed by a file name.

Contact Us

Please report any problems or bugs you might encounter to the Java RTS team.