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.
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.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")
DataSource
MBean operations within
wsadmin
to disable JDBC timing:
AdminControl.invoke(ds, "disableJDBCTiming")
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']])
[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))
- 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).