Advertise with us

Our eBooks

How to trace JDBC statements with JBoss and WildFly

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.

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:

2020-08-19 00:01:13,157 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [DataSource] getConnection()
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [Connection] getAutoCommit()
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [Connection] setAutoCommit(false)
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [Connection] prepareStatement(SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM TRIGGERS WHERE NAME = 'NAME1' AND STATE = ? AND TIME <= ? ) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC)
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [PreparedStatement] setMaxRows(1)
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [PreparedStatement] setFetchSize(1)
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [PreparedStatement] setString(1, WAITING)
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [PreparedStatement] setBigDecimal(2, 1597788103157)
2020-08-19 00:01:13,158 DEBUG [jboss.jdbc.spy] (Thread-0) java:/datasource/mysqlds [PreparedStatement] setBigDecimal(3, 1597788013158)

 Please notice that the spy parameter does not include runtime information about your Datasource statistics, therefore it's not effective to monitor Connection leaks. For that, we recommend setting to "debug" or "error" The Cached Connection Managed in the jca subsystem:

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

 Also, by including the following logger to TRACE, will dump the static and Runtime attribute of your Connection on each usage:

/subsystem=logging/logger=org.jboss.jca/:add(level=TRACE)

 Here's a sample output from the server logs:

2020-08-21 13:04:54,948 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-1) returnConnection(668c5c34, false)
Method: returnConnection(668c5c34, false)
  Subject: null
  CRI: 7d88d179
ManagedConnectionPool:
  Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
  Object: 7179eb80
ManagedConnectionFactory:
  Class: org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory
  Object: 205c500a
ConnectionManager:
  Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
  Object: 63af8ffc
Pool:
  Name: PostgrePool
  Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
  Object: 316a6237
  FIFO: false
PoolConfiguration:
  MinSize: 0
  InitialSize: 0
  MaxSize: 20
  BlockingTimeout: 30000
  IdleTimeoutMinutes: 30
  ValidateOnMatch: false
  BackgroundValidation: false
  BackgroundValidationMillis: 0
  StrictMin: false
  UseFastFail: false
  Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (0):
InUse (1):
  668c5c34 (NORMAL) (CheckedOut: 1598007894938) (Validated: 1598007794843) (Usage: 10)
Statistics:
  ActiveCount: 1
  AvailableCount: 19
  AverageBlockingTime: 0
  AverageCreationTime: 17
  AverageGetTime: 9
  AveragePoolTime: 100086
  AverageUsageTime: 9
  BlockingFailureCount: 0
  CreatedCount: 1
  DestroyedCount: 0
  IdleCount: 0
  InUseCount: 1
  MaxCreationTime: 17
  MaxGetTime: 17
  MaxPoolTime: 100086
  MaxUsageTime: 10
  MaxUsedCount: 1
  MaxWaitTime: 0
  TimedOut: 0

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>
 
© 2021 mastertheboss.com. All Rights Reserved.

Please publish modules in offcanvas position.