How to trace JDBC statements with JBoss and WildFly

User Rating: 5 / 5

Star ActiveStar ActiveStar ActiveStar ActiveStar Active
 
One of the most popular questions asked at JDBC forums is how to debug Statements which are issued to the JDBC driver. Statement Tracing can be done out of the box with the new WildFly application server or JBoss AS 7. If you are using an older version of JBoss application server you can still do it using a free library named P6Spy. We will see both approaches.

JBoss AS 7 and WildFly

In the newest versions of the application server Statement tracing can be accomplished by setting to true the datasource property named spy:
/subsystem=datasources/data-source=MySQLPool/:write-attribute(name=spy,value=true)		

In order to debug the JDBC statements in your server logs, you need to create a logger element which traces the jboss.jdbc.spy package. You can do it as follows:

/subsystem=logging/logger=jboss.jdbc.spy/:add(level=TRACE)

Additionally, if you want to activate tracing of your Connection Pool as well, you can enable the cached-connection-manager attribute which will inform you of every connection opening and closing:

/subsystem=jca/cached-connection-manager=cached-connection-manager/:write-attribute(name=error,value=true)

Reload your server configuration and check from your server logs that Statements are correclty traced. Here is for example how you can see from the logs the Statement binding for a PreparedStatement which sets one parameter:

2014-08-13 11:55:31,432 DEBUG [jboss.jdbc.spy] (default task-8) java:jboss/datasources/MySQLDS [Connection] prepareStatement(SELECT * from USERS WHERE login=?)
2014-08-13 11:55:31,433 DEBUG [jboss.jdbc.spy] (default task-8) java:jboss/datasources/MySQLDS [PreparedStatement] setString(1, admin)
2014-08-13 11:55:31,433 DEBUG [jboss.jdbc.spy] (default task-8) java:jboss/datasources/MySQLDS [PreparedStatement] executeQuery()

Having enabled the Cached connection Manager, you should be able to see as well, connection opening and closing. Here is the trace for a connection acquired by the pool:

2014-08-13 11:58:33,936 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-10) Got connection from pool: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@19a8385[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@130c1cc connection handles=0 lastUse=1407923913936 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@1900828 mcp=SemaphoreArrayListManagedConnectionPool@79fe09[pool=MySQLPool]]

Note the Identifier 79fe09 . This is the Connection Id acquired from the pool. In an application which correclty closes Connections, you should find a matching identifier in the connection close trace statements:

2014-08-13 11:58:33,940 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-10) Returning connection to poolorg.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@19a8385[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@130c1cc connection handles=0 lastUse=1407923913940 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@1900828 mcp=SemaphoreArrayListManagedConnectionPool@79fe09[pool=MySQLPool]]

As evidence that you have some problems with your Connections, you will see that the Connection Ids are enlisted as "InUse" in the logs emitted by the CacheManager, but there are no Statements being executed with that Connection Id:

PoolConfiguration:
MinSize: 0
InitialSize: 0
MaxSize: 20
BlockingTimeout: 30000
IdleTimeoutMinutes: 30
BackgroundValidation: false
BackgroundValidationMillis: 0
StrictMin: false
UseFastFail: false
Available (0):
InUse (4):
bfa549 (NORMAL) (Validated: 1407922195508)
623795 (NORMAL) (Validated: 1407922425495)
7227a0 (NORMAL) (Validated: 1407923783364)
19a8385 (NORMAL) (Validated: 1407923913936)

JBoss AS 4/5/6

If you are using an older release of the application server, you can use the P6Spy tool can be used to monitor effectively all the statements which are issued against a database, including the time to execute the statement and the actual SQL, which means that if you are binding parameters in your PreparedStatements, you get also the query with the actual parameters.

On the site documentation I have seen that the JBoss installation guide relates to the 2.x and 3.x release. Here we will show how to install this tool on the newer releases as well.

At first download the file p6spy-install.zip from here:
http://sourceforge.net/projects/p6spy/files/p6spy/1.3/p6spy-install.zip/download

Step # 1

Unzip the file and look for the file p6spy.jar. This file needs to be placed in JBoss lib directory (For JBoss 4.x you can use JBOSS_HOME/server/<server>/lib. With JBoss 5.x or later you can place it under JBOSS_HOME/common/lib)

Step #2

Place the file spy.properties in a folder inside your JBoss distribution. (For example, I have placed into the folder JBOSS_HOME/server/<server>/db )

#Step 3

Add to your server's CLASSPATH, the folder where you have placed the spy.properties. In our example this would be:

set JBOSS_CLASSPATH=%RUN_CLASSPATH%;C:\jboss-4.2.2.GA\server\default\db

Step #4

Edit the DataSource file that points the connections that needs to be traced and change the driver's class to use P6Spy driver. Example, for an Oracle Datasource:
<datasources>
   <local-tx-datasource>
     <jndi-name>ORACLEDS</jndi-name>
        <connection-url>jdbc:oracle:thin:@192.168.1.10:1530:MYSID</connection-url>
        <driver-class>com.p6spy.engine.spy.P6SpyDriver</driver-class>
        <user-name>user</user-name>
        <password>pwd</password>
        <metadata>
            <type-mapping>Oracle9i</type-mapping>
        </metadata>
   </local-tx-datasource>
</datasources>
 

#Step 5

From inside the spy.properties, specify the real Driver name, that you have just replaced in your datasource file. For example:

realdriver=oracle.jdbc.driver.OracleDriver

That's all!

When you execute any query with the Datasource ORACLEDS, P6Spy will log each statement with the following format:

The log file format of spy.log follows:
current time|execution time|category|statement SQL String|effective SQL string
For example:

1278343428665|32|8|statement|select count(*) from meta_parametri where cod_tipo = ?|select count(*) from meta_parametri where cod_tipo = 3

Here we have issued a Statement at the timestamp 1278343428665, which took 32ms. The following number indicates the logging category (you can manage your log by including and excluding categories, which is described in Common Property File Settings). Finally you have two sql statements: at first the one which you have coded and then the actual statement which has been executed by the DB.

What about Hibernate users ? Hibernate users can debug sql statements in two ways: the simple solution is setting the property show_sql to true in your Session Factory Configuration.

        <property name="show_sql">true</property>

However, this approach is not very flexible and produces too much logging. If you want to redirect your SQL logs in a customized file, then you need simply create a category for your logs which references the packages org.hibernate.SQL:
 <appender name="SQLFile" class="org.apache.log4j.RollingFileAppender">
   <param name="File" value="${jboss.server.log.dir}/sql.log"/>
   <param name="Append" value="true"/>
   <param name="MaxFileSize" value="500KB"/>
   <param name="MaxBackupIndex" value="1"/>
   <layout class="org.apache.log4j.PatternLayout">
     <param name="ConversionPattern" value="%d %m%n"/>
   </layout>
 </appender>

 <category name="org.hibernate.SQL" additivity="false">
   <priority value="debug" />
   <appender-ref ref="CONSOLE" />
   <appender-ref ref="SQLFile" />
 </category>
However, this doesn't solve the problem of binding parameters which are sent to the DB and also you don't get time statistics. Enabling P6Spy with Hibernate is pretty easy anyway, all you have to do is referencing the P6Spy Driver class from your Session Factory configuration and specify the real driver name in the file spy.properties.
 <session-factory>
   <property name="hibernate.bytecode.use_reflection_optimizer">false</property>
   <property name="hibernate.connection.driver_class">com.p6spy.engine.spy.P6SpyDriver</property>
   <property name="hibernate.connection.password">password</property>
   <property name="hibernate.connection.url">jdbc:mysql://localhost:3306/mkyong</property>
   <property name="hibernate.connection.username">root</property>
   <property name="hibernate.dialect">org.hibernate.dialect.MySQLDialect</property>
   <property name="show_sql">true</property>

 </session-factory>
 

Advertisement

Related articles available on mastertheboss.com

How to deploy a DataSource in jboss at application level ?

  Do you need to deploy your DataSource along with your Enterpri

JBoss Datasource HA

This tutorial has been updated for the new release of JBoss Appli

JBoss run out of Connections ?

Have you got No ManagedConnections available error message ? well

How to connect to a DataSource from a remote client?

  If you want to connect to your JBoss Connection Pool from a re

JBoss Datasource configuration

A Datasource is a Java Naming and Directory Interface (JNDI) obje

How do I get the list of Datasources available ?

JBOSS AS 4/5 Users You can use either twiddle: $ twiddle.sh que