Troubleshooting long running JDBC transactions
There are two DataSource
MBean operations that are useful for
investigation of long running JDBC transactions.
Enabling and disabling the timing of transactions
The two MBean operations are, enableJDBCTiming
and
disableJDBCTiming
. These operations enable and disable the timing of transactions,
and the output of trace and debug information.
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).