How to trace JDBC statements with JBoss and WildFly

This tutorial covers how to trace JDBC Statements running on the top of WildFly application server or JBoss Enterprise Application Platform.
There are multiple ways to trace SQL Statements:
  1. Use Hibernate/JPA properties (if your application is using it)
  2. Configure P6Spy tool on WildFly (if you are issuing plain SQL Statements)
  3. Configure your JDBC Driver to trace statements (if available)

Logging with JPA

In order to trace JPA Statements, you have to enable the right property for your JPA Provider.
For example, if using Hibernate as JPA Provider
<property name = "hibernate.show_sql" value = "true" />

If using EclipseLink:

<property name="eclipselink.logging.level" value="FINE"/>

If using OpenJPA:

<property name="openjpa.Log" value="DefaultLevel=WARN,Runtime=INFO,Tool=INFO,SQL=TRACE"/>

Logging plain JDBC Statements

A simple and effective way to log SQL statements is to use a free library named P6Spy.
This can be accomplished by setting to true the datasource property named spy. From the CLI execute:
/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 correctly 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

Tracing statements using the JDBC Driver

As an alternative, you can leverage the native features (if any) of your JDBC Driver to allow tracing of SQL Statements.

As an example, for Oracle JDBC Driver you can enable logging by setting the oracle.jdbc.Trace system property:

java -Doracle.jdbc.Trace=true

Setting the system property enables global logging, which means that logging is enabled for the entire application. You can use global logging if you want to debug the entire application, or if you cannot or do not want to change the source code of the application.

On the other hand, if using MySQL Database, the following properties can be appended to the JDBC URL to enable logging

&logger=com.mysql.jdbc.log.Slf4JLogger&profileSQL=true

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>