Troubleshooting long running JDBC transactions

You can use the enableJDBCTiming and disableJDBCTiming MBean operations to investigate long running JDBC transactions. These operations enable and disable the timing of transactions, and the output of trace and debug information.

Enabling and disabling the timing of transactions

The enableJDBCTiming operation takes a target object of the DataSource on which timing is to be enabled, and a threshold parameter in milliseconds. This parameter controls how long a transaction on the specified DataSource can run before it causes the output of trace and debug information about the transaction. This trace and debug information can be used to determine the cause of a long running transaction and to help understand the performance of certain SQL statements. When the enableJDBCTiming operation is executed, timing begins for any transactions started afterward. Transactions already in progress are not timed.

The disableJDBCTiming operation turns off any further timing of SQL statements and any associated output. You can dynamically turn timing on and off to capture information to try and determine the cause of a long running transaction by using the mbean operations. If the server is restarted, the state of the JDBC timing is not maintained. If you want to enable JDBC timing permanently, you can add a custom property that is named JDBCTimingThreshold with the desired value in milliseconds to the desired DataSource, either by using the Administrative Console, or wsadmin commands. If this property exists when the server is started, JDBC timing begins before any transactions are started and continues until either the disableJDBCTiming mbean operation is called, or the property is deleted and the server restarted.

Note: Sensitive data could be logged if JDBC timing is enabled and the SQL statements that are being executed contain sensitive data. This logging might occur irrespective of the

Disable
logging and tracing of sensitive data

logging configuration setting. Because enabling JDBC timing involves tracking of all SQL statements for a datasource, it has an impact on the performance of the application server. The degree of impact depends on a number of factors that include hardware specification, transaction throughput, and other factors. When you enable JDBC timing on a production server, test to verify that any performance difference is acceptable.

Jython syntax for using DataSource MBean operations within wsadmin to enable JDBC timing with a threshold of 18 seconds:

ds = AdminControl.completeObjectName('name=DefaultApp Datasource,*')
AdminControl.invoke(ds, "enableJDBCTiming","18000")

Jython syntax for using DataSource MBean operations within wsadmin to disable JDBC timing:

AdminControl.invoke(ds, "disableJDBCTiming")

Jython syntax for using DataSource MBean operations within wsadmin to persist the threshold value by adding it as a custom property to a data source:

ds = AdminConfig.getid( '/Cell:MyCell/Node:MyNode/Server:server1/JDBCProvider:Derby JDBC Provider/DataSource:DefaultApp Datasource/')
propertySet = AdminConfig.showAttribute(ds, 'propertySet')
AdminConfig.create('J2EEResourceProperty', propertySet, [['name','JDBCTimingThreshold'], ['value','180000'],['description','Log a stacktrace and list of JDBC operations that are performed if a transaction runs for more than the specified number of milliseconds']])

How the JDBC timing output might look:

[4/7/17 9:04:38:618 CDT] 000000a0 WSJdbcTiming  W   TRAS9910W: The 7555828d transaction on the
000000a0 thread has been running for       1044 ms, which exceeds the time set for emitting the trace on a
running thread. The following stack trace shows what this thread is currently doing:java.lang.Throwable
 at com.ibm.ws.rsadapter.spi.WSJdbcTiming.<init>(WSJdbcTiming.java:39)
 at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.beginTransactionIfNecessary(WSJdbcConnection.java:872)
 at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.createStatement(WSJdbcConnection.java:1729)
 at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.createStatement(WSJdbcConnection.java:1707)
 at suite.r90.base.jdbc41.test.JDBC41TestServlet.init(JDBC41TestServlet.java:136)
 at javax.servlet.GenericServlet.init(GenericServlet.java:244)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:342) 
 at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.init(ServletWrapperImpl.java:168) 
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.load(ServletWrapper.java:1385)
 at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1029)
 at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:4144)
 at com.ibm.ws.webcontainer.webapp.WebAppImpl.handleRequest(WebAppImpl.java:2208) 
 at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:304)
 at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:1030)
 at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1817)
 at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:382)
 at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:465)
 at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:532)
 at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:318)
 at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.ready(HttpInboundLink.java:289)
 at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:214)
 at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:113)
 at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:175)
 at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
 at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
 at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138) 
 at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)
 at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775) 
 at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)
 at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1892) 
The following list gives the total run time of the transaction, all SQL statements that ran during the
transaction, and the run time for each of the SQL statements:
   1044 ms  JEEName:jdbc41testApp | jdbc41test.war | JDBC41TestServlet 
  814.845 ms  jdbc/TestDataSource | executeUpdate | drop table JDBC_FAT_v41_COLORS 
  213.501 ms  jdbc/TestDataSource | executeUpdate | create table JDBC_FAT_v41_COLORS (id int not null primary key, color
    varchar(30))

The first line after the TRAS9910W message contains the total time of the transaction so far, followed by the name of the application. For each SQL statement executed as part of the transaction, there is a following line with the field format:

Time for method completion (814.845ms).
JNDI name of the Data Source on which the SQL statement was executed (jdbc/TestDataSource).
JDBC specification method that is called by application (executeUpdate).
SQL statement that is executed (drop table JDBC_FAT_v41_COLORS).