Friday June 09, 2006 
Today's Page Hits: 25
Friday June 09, 2006 Part One: The Dtrace Method provider
I intend to prepare a few blog entries that present the hotspot provider facilities as, I think the topic is too big for one blog entry. I have decided to break them up into functional groups. I am starting with the application method probes as this is the first place I start looking when I am looking for the cause of a slow application and then onto the method compilation probes.
In my opinion one of the best advances in Java, since generics, is the inclusion of the DTrace hotspot provider. This, while being a non GUI solution to profiling for the time being, could be the way we all do profiling in the future. In this blog entry I am going to discuss some of the cool things about the hotspot provider method tracing and how it can help us understand the application in question better.
I created a simple Java application for us to examine that creates a lockfile in /tmp, called myLock, then starts 5 threads that all check for the existance of this file then loop sleeping for a second wake up check for the file then sleep for again. When the file is deleted as the threads wake and detect this fact,they then exit. Quite simple and contrived but it is all we need to see the hotspot method probes in action.
Before we go any further I need to explain my environment. This article is based on the use of Mustang, (Java SE 6) build 84 and on OpenSolaris (Navada) build 40 for clarity I have provided the Java and OS versions I have used while developing this article. Please let me know if something does not work for you.
$ java -version
java version "1.6.0-beta2"
Java(TM) SE Runtime Environment (build 1.6.0-beta2-b84)
Java HotSpot(TM) Client VM (build 1.6.0-beta2-b84, mixed mode, sharing)
$ uname -a
SunOS squarepants 5.11 snv_40 i86pc i386 i86pc
The Hotspot method probes
We need start this by understanding the process I am using. I have found if you want to trace the whole Java life cycle or short lived programs the simplest solution is to use the -XX:+PauseAtStartup JVM switch. This initialses the JVM but does not start executing the Java program. It also creates a lock file of sorts in the current working directory named vm.paused.<PID> where <PID> is the proceess id. The examples in this article use this pid as an agument to the dtrace script. If you are not interested in JVM lifecycle probes there are easer ways of starting the application, like using the -c option when executing your dtrace script.
The Application Tracking Probes
- method-entry
- method-return
The arguments for these probes follow
- arg[0] Java thread id that is entering/leaving method
- arg[1] Pointer to string containing the name of class
- arg[2] Length of the class name
- arg[3] Pointer to string containing the method name
- arg[4] Length of the method name
- arg[5] Pointer to string containing the method signature
- arg[6]Length of the method signature
To use the method probes you need one of the following JVM flags:
-XX:+ExtendedDTraceProbes (turns all of the application probes on).
-XX:+DTraceMethodProbes (turns on method probes).
Both of these flags can cause performace degredation in the VM so use with care. In order to use the -XX:+PauseAtStartup JVM switch flag another flag needs to be set -XX:+UnlockDiagnosticVMOptions. Here is the commandline I used to execute the Java application in order to trace the methods.
java -XX:+UnlockDiagnosticVMOptions -XX:+PauseAtStartup -XX:+DTraceMethodProbes dtracedemo.ThreadExample
We need a few terminal windows here in the first terminal I enter the command above, after I hit return the application appears to do nothing. In the second window, in the same CWD I can see the file vm.paused.1167. So I know that the pid that I need is 1167. In the third terminal I execute the dtrace script (./nv_app_track_time_depth.d -p 1167). At this point in the third terminal DTrace will report "BEGIN Java method entry/return tracing" We can now go back to the second terminal and remove the vm.paused.1167 file to allow the execution of the Java application to continue. Next, for this example, I remove the lock file (/tmp/myLock) and the application exits and dtrace reports the infomation gathered in the third terminal.
Here are the class names and methods of the ten methods that occupied the most time (ms) of the application run as produced by nv_app_track_time_depth.d.
37 java/io/File/<clinit>
37 java/io/FileSystem/getFileSystem
37 java/io/UnixFileSystem/<init>
39 java/lang/ClassLoader/loadClass
53 sun/misc/Launcher/<clinit>
53 sun/misc/Launcher/<init>
54 java/lang/ClassLoader/getSystemClassLoader
54 java/lang/ClassLoader/initSystemClassLoader
62 java/security/AccessController/doPrivileged
72 java/io/ExpiringCache/<init>
Another interesting statistic might be, what is the number of times each of these methods have been called?
nv_app_track_number.d.
402 java/util/HashMap/indexFor
439 java/lang/String/<init>
502 java/lang/String/hashCode
550 java/lang/Character/toLowerCase
554 java/lang/System/arraycopy
589 java/lang/StringBuilder/append
608 java/lang/AbstractStringBuilder/append
842 java/lang/String/indexOf
1460 java/lang/Object/<init>
5567 java/lang/String/charAt
At this point it would easy enough to see other interesting things we can do with this information. So how about how long did a particular method take to compile on the hotspot compiler?
Method Compilation Probes
- method-compile-begin
- method-compile-end
Method compilation arguments
- arg[0] Pointer to string containing compiler name
- arg[1] Length of compiler name in bytes
- arg[2] Pointer to string containing compiled class name
- arg[3] Length of class name in bytes
- Pointer to string containing compiled method name
- Length of method name
- Pointer to string containing method signature
- Length of method signature in bytes.
Output from nv_method_compile.d
Method compliled = java/lang/String/hashCode took 1493 us
Method compliled = java/lang/String/equals took 666 us
Method compliled = java/lang/String/indexOf took 1063 us
Method compliled = java/lang/String/charAt took 395 us
Method compliled = java/lang/String/lastIndexOf took 921 us
Method compliled = java/io/UnixFileSystem/normalize took 781 us
Method compliled = java/lang/String/indexOf took 1150 us
Method compliled = java/lang/Object/<init> took 251 us
The Example Code used in this blog
Here is the simple Java application I wrote as an example we can use to examine the use of the hotspot method probes.
MyThread.java
package dtracedemo;
import java.io.*;
/*
* Copyright 2006 Sun Microsystems, Inc. All rights reserved.
* Use is subject to license terms.
*
* This is part of the Intro to Java DTrace developed by
* Damien Cooke (Damien.Cooke@Sun.COM)
*
*/
class MyThread extends Thread
{
public void run()
{
File thefile = new File("/tmp/myLock");
while(thefile.exists() == true)
{
try{this.sleep(1000);}catch(java.lang.InterruptedException ie){}
}
System.out.println("Thread "+ this.getId() +" exiting");
}
}
ThreadExample.java
package dtracedemo;
import java.io.*;
import java.util.Vector;
/*
* Copyright 2006 Sun Microsystems, Inc. All rights reserved.
* Use is subject to license terms.
*
* This is part of the Intro to Java DTrace developed by
* Damien Cooke (Damien.Cooke@Sun.COM)
*
*/
class ThreadExample
{
public static void main(String[] args)
{
Vector v = new Vector();
try
{
BufferedOutputStream bos = new BufferedOutputStream(new FileOutputStream(new File("/tmp/myLock")));
bos.write(3);
bos.close();
for(int i = 0; i < 4; i++)
{
MyThread mt = new MyThread();
v.addElement((MyThread)mt);
System.out.println("Thread number "+v.size()+" created" );
}
for(int i = 0; i < 4; i++)
{
((MyThread)v.elementAt(i)).run();
}
}catch(IOException e){}
}
}
nv_app_track_time_depth.d
#pragma D option quiet
this char *str_ptr;
this string signature;
this string return_class_name;
this string return_method_name;
BEGIN
{
printf("BEGIN Java method entry/return tracing\n");
}
hotspot$target:::method-entry
{
this->return_class_name = copyinstr(arg1, arg2);
this->return_method_name = copyinstr(arg3, arg4);
self->ts[ustackdepth] = vtimestamp;
}
hotspot$target:::method-return
{
this->return_class_name = copyinstr(arg1, arg2);
this->return_method_name = copyinstr(arg3, arg4);
this->delta = (vtimestamp - self->ts[ustackdepth]);
@sums[this->return_class_name,this->return_method_name] = sum(this->delta);
self->ts[ustackdepth] = 0;
}
END
{
printf("\nTotal time spent in methods (ms):");
normalize(@sums,1000000);
printa("%10@d %s/%s\n",@sums);
}
nv_app_track_number.d
#pragma D option quiet
#pragma D option destructive
/*
* Copyright 2006 Sun Microsystems, Inc. All rights reserved.
* Use is subject to license terms.
*
* This is part of the Intro to Java DTrace developed by
* Damien Cooke (Damien.Cooke@Sun.COM)
*
*/
this char *str_ptr;
this string entry_class_name;
this string entry_method_name;
this string return_class_name;
this string return_method_name;
BEGIN
{
printf("BEGIN Java method entry/return tracing\n");
}
hotspot$target:::method-entry
{
this->entry_class_name = copyinstr(arg1,arg2);
this->entry_method_name = copyinstr(arg3,arg4);
@count[this->entry_class_name,this->entry_method_name]=count();
}
END
{
printf("\nTotal times method was executed:");
printa("%10@d %s/%s\n", @count);
}
nv_method_compile.d
#pragma D option quiet
#pragma D option destructive
self char *str_ptr;
self string compile_class_name;
self string compile_method_name;
self string load_class_name;
self string load_method_name;
BEGIN
{
printf("BEGIN Java compilation tracing\n");
}
hotspot$target:::method-compile-begin
{
self->ts[ustackdepth] = vtimestamp;
}
hotspot$target:::method-compile-end
{
this->compile_class_name = copyinstr(arg2,arg3);
this->compile_method_name = copyinstr(arg4,arg5);
printf("Method compliled = %s/%s took %d us\n",this->compile_class_name,this->compile_method_name,((vtimestamp - self->ts[ustackdepth])/1000));
self->ts[ustackdepth] = 0;
}
Please let me know if there are any omissions or mistakes. I have tested them all but OpenSoalris (and Navada) are in development and Mustang in in beta.