WebSphere Application Server traditional periodically adds new diagnostic tools with new fixpacks. This posts covers the enableJDBCTiming tool added in WAS 22.214.171.124 and 126.96.36.199 to help administrators discover the cause of slow database transactions.
In WAS traditional, there are many ways to investigate database response times such as 3rd party monitoring tools, Performance Monitoring Infrastructure (PMI), Tivoli Performance Viewer (TPV), Request Metrics, hung thread detection, thread dumps, PreparedStatement diagnostic trace, sampling profilers, and more.
However, each of these tools and approaches has its own baggage, complexity, and/or overhead. Sometimes, all you need is: If the database response time is taking longer than X milliseconds, tell me why in a low overhead way.
This is exactly what enableJDBCTiming does. You may enable it dynamically at runtime using an MBean, or at start-up by adding a custom data source property. You specify the threshold in milliseconds. If a query takes longer than this threshold, a warning is printed to SystemOut.log when a connection is returned to the pool with all SQL statements executed with that connection, their response times, and the enclosing request details (e.g. servlet name). For example:
[2/15/21 16:01:25:251 UTC] 000000e4 WSJdbcTiming W TRAS9910W: The 747e7a15 transaction on the 000000e4 thread has been running for 1300 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:
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:
1303 ms JEEName:DayTrader7 | daytrader-ee7-web.war | TradeAppServlet
0.062 ms jdbc/TradeDataSource | psExecuteQuery | select * from orderejb o where o.orderstatus = 'closed' AND o.account_accountid = (select a.accountid from accountejb a where a.profile_userid = ?)
1301.738 ms jdbc/TradeDataSource | psExecuteUpdate | update orderejb set orderstatus = ?, completiondate = ? where orderid = ?
0.035 ms jdbc/TradeDataSource | psExecuteQuery | select * from accountejb a where a.profile_userid = ( select userid from accountprofileejb ap where ap.userid = ?)
0.041 ms jdbc/TradeDataSource | psExecuteQuery | select * from accountprofileejb ap where ap.userid = (select profile_userid from accountejb a where a.profile_userid=?)
To enable this tool, start wsadmin:
$WAS/profiles/$PROFILE/bin/wsadmin.sh -lang jython
If you don't remember the data source name, you may list all data sources:
['DefaultEJBTimerDataSource(cells/DefaultCell01/nodes/DefaultNode01/servers/server1|resources.xml#DataSource_1000001)', 'NoTxTradeDataSource(cells/DefaultCell01/nodes/DefaultNode01/servers/server1|resources.xml#DataSource_1610402373703)', 'TradeDataSource(cells/DefaultCell01/nodes/DefaultNode01/servers/server1|resources.xml#DataSource_1610402372443)', 'built-in-derby-datasource(cells/DefaultCell01|resources.xml#DataSource_9007001)']
Then take the data source name and put it into the following command, and specify your threshold in milliseconds. For example:
wsadmin>AdminControl.invoke(AdminControl.completeObjectName('name=TradeDataSource,*'), "enableJDBCTiming", "1000")
To dynamically disable the timing:
This is a useful tool to add your toolbox to help understand poorly performing database transactions.
Note: remember that database query response times do not necessarily mean that the database is slow. It could also be that WAS had a long garbage collection or there is a network issue, so all facets should be investigated if possible.
If you want to try this out yourself, you may use the free WAS traditional DayTrader benchmark lab and set the threshold to something small like 10 milliseconds. This lab is covered in our previous post in this series: Lessons from the field #1 - A free Troubleshooting and Performance Lab.