A few months back, I got wind from the world famous Jarod Jenson that Keith McGuigan was working on adding JSDT probes to Java. JSDT probes struck me as an extremely useful feature for realtime problem analysis, so I decided to instrument some sample code to see how they worked. After a couple of e-mail exchanges with Keith, I had a working Java build that supported JSDT. After reviewing a number of Java projects, I chose to instrument the PostgreSQL Java type IV driver, since I wanted to learn PostgreSQL along with JDBC. After reading through a fair amount of the PostgreSQL type IV driver code and Keith’s blog, I decided to add the following probes to the postgreSQL driver:
$ dtrace -l -m java_tracing
ID PROVIDER MODULE FUNCTION NAME
13199 postgresqljdbc1619 java_tracing unspecified transactioncommit
13200 postgresqljdbc1619 java_tracing unspecified transactionrollback
13201 postgresqljdbc1619 java_tracing unspecified executesqlstatementstart
13202 postgresqljdbc1619 java_tracing unspecified getconnectionfrompoolstop
13203 postgresqljdbc1619 java_tracing unspecified executepreparessqlstatementstart
13204 postgresqljdbc1619 java_tracing unspecified transactionautomcommit
13205 postgresqljdbc1619 java_tracing unspecified releaseconnectionstop
13206 postgresqljdbc1619 java_tracing unspecified getconnectionfrompoolstart
13207 postgresqljdbc1619 java_tracing unspecified executepreparedsqlstatementstop
13208 postgresqljdbc1619 java_tracing unspecified returnconnectiontopoolstop
13209 postgresqljdbc1619 java_tracing unspecified transactionsavepoint
13210 postgresqljdbc1619 java_tracing unspecified acquireconnectionstart
13211 postgresqljdbc1619 java_tracing unspecified returnconnectiontopoolstart
13212 postgresqljdbc1619 java_tracing unspecified releaseconnectionstart
13213 postgresqljdbc1619 java_tracing unspecified acquireconnectionstop
13214 postgresqljdbc1619 java_tracing unspecified executesqlstatementstop
DTrace uses providers to group probes, so the first thing I did was create a “postgresqljdbc " provider that would be visible to DTrace through the JSDT framework. This was achieved by defining an interface that extended the com.sun.tracing.Provider class:
package org.postgresql;
public interface postgresqljdbc extends com.sun.tracing.Provider {
// Probes that fire when a simple SQL statement begins / ends execution
void executesqlstatementstart(String query);
void executesqlstatementstop(String query);
// Probes that fire when a prepared statement begins / ends execution
void executepreparessqlstatementstart(String query);
void executepreparedsqlstatementstop(String query);
// Probe that fires when a new connection is established / released
void acquireconnectionstart(String host, int port, String database, String user);
void acquireconnectionstop(String host, int port, String database, String user);
void releaseconnectionstart(String host, int port, String user, String passwd);
void releaseconnectionstop(String host, int port, String user, String passwd);
// Probes that fire when a DB connection pool is accessed / released
void getconnectionfrompoolstart(String host, int port, String user, String passwd);
void getconnectionfrompoolstop(String host, int port, String user, String passwd);
void returnconnectiontopoolstart(String host, int port, String user, String passwd);
void returnconnectiontopoolstop(String host, int port, String user, String passwd);
// Probe that fires when a transaction starts, saves, commits or rolls back
void transactionautomcommit(boolean value);
void transactionsavepoint(String value);
void transactioncommit();
void transactionrollback();
}
Now that the provider was defined, I needed to import the Provider and ProviderFactory classes that are part of the JSDT framework, and add the code to instantiate a new postgresqljdbc object:
import com.sun.tracing.Provider;
import com.sun.tracing.ProviderFactory;
public class Driver implements java.sql.Driver
{
.....
public static ProviderFactory factory = ProviderFactory.getDefaultFactory();
public static postgresqljdbc provider = factory.createProvider(postgresqljdbc.class);
Next, I started adding probe points to the driver. This was super easy, since probe points are defined by a call to one of the provider methods that are defined in the interface that extends the Provider class. Here are the probes I added to capture SQL statement execution:
public boolean executeWithFlags(String p_sql, int flags) throws SQLException
{
org.postgresql.Driver.provider.executesqlstatementstart(p_sql);
checkClosed();
p_sql = replaceProcessing(p_sql);
Query simpleQuery = connection.getQueryExecutor().createSimpleQuery(p_sql);
execute(simpleQuery, null, QueryExecutor.QUERY_ONESHOT | flags);
this.lastSimpleQuery = simpleQuery;
org.postgresql.Driver.provider.executesqlstatementstop(p_sql);
return (result != null && result.getResultSet() != null);
}
In this specific code block, I added the “org.postgresql.Driver.provider.executesqlstatementstart” probe which fires when the SQL statement begins execution, and a “executesqlstatementstop” probe that fires after the SQL statement has executed. In both cases, the argument available to DTrace scripts is the SQL statement (represented as a String) that is being executed.
Next up, I ran ant to build a new postgreSQL driver, and executed a test program to verify everything worked:
$ export CLASSPATH=/home/matty/java/postgrestest:/home/matty/java/postgrestest/postgresql.jar
$ export JAVA_HOME=/usr/java/
$ java -Djdbc.drivers=org.postgresql.Driver -XX:+ExtendedDTraceProbes Test
The Test program does nothing more than create SQL connections, execute SQL statements and print the results to STDOUT. To allow me to see the difference between prepared and unprepared statements, I decided to add unique probes for each statement type.
After debugging a few issues, I was able to run the Test program and a few DTrace scripts I had created. The first script, sqlconnections.d, listed new connections to the database and the time it took to create these connections:
$ ./sqlconnections.d
TIMESTAMP HOST PORT DATABASE USER TIME
2008 Oct 10 15:59:47 localhost 5432 postgres matty 17048632
2008 Oct 10 15:59:51 localhost 5432 postgres matty 17597898
The next script, sqltimes.d, listed all of the SQL statements that were executed along with the total time they had run:
$ sqltimes.d
Tracing started (CNTRL+C to end)
^C
SQL statements:
SQL QUERY COUNT TIME
update matty set col1='one' 2 722359
select * from matty 4 1456311
Prepared statements:
SQL QUERY COUNT TIME
update matty set col1='one' 2 548765
select * from matty 4 1345987
The third script, sqltrace.d, displayed each SQL statement executed along with the time it had executed:
$ ./sqltrace.d
TIMESTAMP SQL QUERY TIME
1970 Mar 1 16:59:06 select * from matty 314021
1970 Mar 1 16:59:06 select * from matty 251793
1970 Mar 1 16:59:06 update matty set col1='one' 308901
I also had fun playing with transactions and JDBC connection pool probes, but that data wasn’t nearly as interesting as the SQL statement execution times listed above. If you are running openjdk on Solaris, and you want to get better visibility into your applications, JSDT may well be worth a look! I’m still not 100% sure what kind of performance impact these probes will have on an application, but will wait for the probes to be integrated into a mainsteam Java build prior to doing any real performance testing. Thanks Keith for answering my e-emails, and to team DTrace for creating the awesomeness that is DTrace!