Friday Aug 08, 2008

Scriptifying BTrace?

One of the issues reported with BTrace is that the trace authors have to write "verbose" code [some people say Java is "verbose"!]. In BTrace, we have to repeat the same set of imports, annotations in every btrace file and all methods have to be "public static void" and so on. Instead of inventing a new scripting language, I've added a simple C preprocessor like step in BTrace compilation. This preprocessor is based on the one in the GlueGen project. Thanks to Ken Russell for this code and for reviewing my changes specific to BTrace project. The preprocessor solution does not rule out a scripting solution in future :-) If you have nice ideas or would like contribute in this area, you are always welcome! But, I think preprocessor solution is simple and will be useful to some.


Simple Example:


btracedefs.h
ThreadBean.java

To run this sample, the following command can be used:

   btrace -I . <pid-of-the-traced-process> ThreadBean.java

Without the -I option in command line, BTrace skips the preprocessor step.

Friday Jul 18, 2008

BTrace and JMX

You can dyanamically attach BTrace to a Java process to inject trace code into it. BTrace client classescollect the trace output via a socket -- these client classes are used by BTrace command line client as well as VisualVM plugin for BTrace. How about attaching a JMX client to collect BTrace's trace data? Yes, it is possible to access a BTrace class's static fields as attributes of a MBean with this RFE.

There are two MBean samples in the BTrace repository. I attached both BTrace samples to a "Java2D demo" process. And then I attached VisualVM to view the Mbean registered by these BTrace samples:

  1. ThreadCounterBean.java - this sample instruments java.lang.Thread.start() method to update a counter field. This counter field is accessible by JMX clients.



  2. HistogramBean.java - this sample collects histogram of java.awt.Component objects created by an application and exposes the histogram (map) as MBean attribute.


Monday Jun 16, 2008

BTrace in the real world

In the last few weeks, I came to know about two cases of real world use of BTrace.
  1. Glencross, Christian M (his blog?) wrote about attempting to write a script to track SQL statements executed by a Java application (private email). Thanks to him for permitting me to blog about his BTrace script. I've made few formatting changes to fit his code in this blog and added few explanatory comments (staring with "VERBOSE:").
    
    
    import static com.sun.btrace.BTraceUtils.\*;
    
    import java.sql.Statement;
    import java.util.Map;
    import java.util.concurrent.atomic.AtomicLong;
    
    import com.sun.btrace.\*;
    import com.sun.btrace.annotations.\*;
    
    /\*\*
     \* BTrace script to print timings for all executed JDBC statements on an event.
     \* <p>
     \* 
     \* @author Chris Glencross
     \*/
    @BTrace
    public class JdbcQueries {
    
        private static Map preparedStatementDescriptions = newWeakMap();
    
        private static Map statementDurations = newHashMap();
    
        // VERBOSE: @TLS makes the field "thread local" -- sort of like using java.lang.ThreadLocal
        @TLS
        private static String preparingStatement;
    
        @TLS
        private static long timeStampNanos;
    
        @TLS
        private static String executingStatement;
    
        /\*\*
         \* If "--stack" is passed on command line, print the Java stack trace of the JDBC statement.
         \*
         \* VERBOSE: Command line arguments to BTrace are accessed as $(N) where N is the command line arg position.
         \* 
         \* Otherwise we print the SQL.
         \*/
        private static boolean useStackTrace = $(2) != null && strcmp("--stack", $(2)) == 0;
    
        // The first couple of probes capture whenever prepared statement and callable statements are
        // instantiated, in order to let us track what SQL they contain.
    
        /\*\*
         \* Capture SQL used to create prepared statements.
         \*
         \* VERBOSE: +foo in clazz means foo and it's subtypes. Note the use of regular expression
         \* for method names. With that BTrace matches all methods starting with "prepare". The
         \* type "AnyType" matches any Java type.
         \* 
         \* @param args - the list of method parameters. args[1] is the SQL.
         \*/
        @OnMethod(clazz = "+java.sql.Connection", method = "/prepare.\*/")
        public static void onPrepare(AnyType[] args) {
            preparingStatement = useStackTrace ? jstackStr() : str(args[1]);
        }
    
        /\*\*
         \* Cache SQL associated with a prepared statement.
         \*
         \* VERBOSE: By default, @OnMethod matches method entry points. Modifying with @Location 
         \* annotation to match the method return points.
         \* 
         \* @param arg - the return value from the prepareXxx() method.
         \*/
        @OnMethod(clazz = "+java.sql.Connection", method = "/prepare.\*/", location = @Location(Kind.RETURN))
        public static void onPrepareReturn(AnyType arg) {
            if (preparingStatement != null) {
                print("P"); // Debug Prepared
                Statement preparedStatement = (Statement) arg;
                put(preparedStatementDescriptions, preparedStatement, preparingStatement);
                preparingStatement = null;
            }
        }
    
        // The next couple of probes intercept the execution of a statement. If it execute with no-args,
        // then it must be a prepared statement or callable statement. Get the SQL from the probes up above.
        // Otherwise the SQL is in the first argument.
    
        @OnMethod(clazz = "+java.sql.Statement", method = "/execute.\*/")
        public static void onExecute(AnyType[] args) {
            timeStampNanos = timeNanos();
            if (args.length == 1) {
                // No SQL argument; lookup the SQL from the prepared statement
                Statement currentStatement = (Statement) args[0]; // this
                executingStatement = get(preparedStatementDescriptions, currentStatement);
            } else {
                // Direct SQL in the first argument
                executingStatement = useStackTrace ? jstackStr() : str(args[1]);
            }
        }
    
        @OnMethod(clazz = "+java.sql.Statement", method = "/execute.\*/", location = @Location(Kind.RETURN))
        public static void onExecuteReturn() {
    
            if (executingStatement == null) {
                return;
            }
    
            print("X"); // Debug Executed
    
            long durationMicros = (timeNanos() - timeStampNanos) / 1000;
            AtomicLong ai = get(statementDurations, executingStatement);
            if (ai == null) {
                ai = newAtomicLong(durationMicros);
                put(statementDurations, executingStatement, ai);
            } else {
                addAndGet(ai, durationMicros);
            }
    
            executingStatement = null;
        }
    
        // VERBOSE: @OnEvent probe fires whenever BTrace client sends "event" command.
        // The command line BTrace client sends BTrace events when user pressed Ctrl-C 
        // (more precisely, on receiving SIGINT signal)
        @OnEvent
        public static void onEvent() {
            println("---------------------------------------------");
            printNumberMap("JDBC statement executions / microseconds:", statementDurations);
            println("---------------------------------------------");
        }
    
    }
    
    

    And he has expressed few wish lists for BTrace based on his experience with DTrace. We plan to investigate those items in near future.



  2. Binod P.G exchanged private e-mails about BTrace usage to track down a memory leak. Subsequently, he has blogged about the same.

Tuesday Apr 29, 2008

BTrace BOF @ JavaOne 2008

We have a BOF on BTrace in this year's JavaOne. But, you will not find the name "BTrace" in session title -- that is because talk was submitted before BTrace was open sourced with that name :-) The details of the BOF is as below. Please visit and let us discuss on dynamic tracing for Java.

BOF-5552 Java™ Platform Observability by Bytecode Instrumentation Kannan Balasubramainan, A. Sundararajan Tuesday May 06 19:30 - 20:20 Moscone Center - Esplanade 300


Other related talks/BOFs on dynamic tracing/observability include:

Moscone Center - Hall E 133
TS-5716 D-I-Y (Diagnose-It-Yourself): Adaptive Monitoring for Sun Java™ Real-Time System Technical Session Carlos Lucasius, Frederic Parain Tuesday May 06 18:00 - 19:00
TS-6000 Improving Application Performance with Monitoring and Profiling Tools Technical Session Jaroslav Bachorik, Gregg Sporar Wednesday May 07 10:50 - 11:50 Moscone Center - Gateway 104
LAB-9400 Exposing the Depth of Your JDK™ Release 7.0 Applications with Dynamic Tracing (DTrace) Hands-On Lab Angelo Rajadurai, Raghavan Srinivas, Wednesday May 07 18:30 - 20:30 Moscone Center - Hall E 130/131 (LAB)
TS-6145 Using DTrace with Java™ Technology-Based Applications: Bridging the Observability Gap Technical Session Jonathan Haslam, Simon Ritter Thursday May 08 13:30 - 14:30 Moscone Center - North Mtg-121/122/124/125
BOF-4994 End-to-End Tracing of Ajax/Java™ Technology-Based Applications, Using Dynamic Tracing (dTrace) Birds-of-a-Feather Session (BOF) Amit Hurvitz Thursday May 08 18:30 - 19:20 Moscone Center - Gateway 104
BOF-5223 VisualVM: Integrated and Extensible Troubleshooting Tool for the Java™ Platform Birds-of-a-Feather Session (BOF) Luis-Miguel Alventosa, Tomas Hurka Thursday May 08 19:30 - 20:20 Moscone Center - Gateway 104
TS-6145 Using DTrace with Java™ Technology-Based Applications: Bridging the Observability Gap Technical Session Jonathan Haslam, Simon Ritter Friday May 09 14:50 - 15:50 Moscone Center - North Mtg-121/122/124/125
TS-6000 Improving Application Performance with Monitoring and Profiling Tools Technical Session Jaroslav Bachorik, Gregg Sporar Friday May 09 16:10 - 17:10 Moscone Center - Hall E 133
About

sundararajan

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
Bookmarks
Links

No bookmarks in folder

Blogroll

No bookmarks in folder

News

No bookmarks in folder