Friday Jun 09, 2006

Dtrace Java Methods using Java SE 6

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

#!/usr/sbin/dtrace -s

#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



#!/usr/sbin/dtrace -s

#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

#!/usr/sbin/dtrace -s

#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.









About

damiencooke

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today