Timed operations and JDBC calls

Timed operations generate a logged warning when JDBC calls in the application server are operating more slowly or quickly than expected.

Overview

When enabled, the timed operation feature tracks the duration of JDBC operations running in the application server. In cases where operations take more or less time to execute than expected, the timed operation feature logs a warning. Periodically, the timed operation feature will create a report, in the application server log, detailing which operations took longest to execute. If you run the server dump command, the timed operation feature will generate a report containing information about all operations it has tracked. You can use the information listed in these reports to decide if anything is running slower or faster than you expect.

Periodically, the system generates a report to the logs that contains the ten longest JDBC timed operations. The frequency and enablement of this report is configurable in the server.xml file, with a default of once per day (24 hours).

To enable timed operations, add the timedOperations-1.0 feature to the server.xml file.

Stabilized feature: The timedOperations-1.0 feature is stabilized. There is no strategic alternative. You can continue to use the timedOperations-1.0 feature.

Customize timed operations

You can disable the generation of the report to the logs, or change the frequency of the report, for example to once every 12 hours, using the timedOperation element as shown in the following example:

<timedOperation enableReport="false" reportFrequency="12" />

The server limits the number of tracked timed operations to the value specified in the maxNumberTimedOperations attribute automatically. A warning is logged when the total number of timed operations reaches the maximum value specified.

<timedOperation enableReport="false" reportFrequency="12" maxNumberTimedOperations="10000"/>

To limit the number of tracked timed operations, the least recently used timed operation record is deleted when a new timed operation is required to be tracked. When the number of timed operations that are tracked reaches the specified maximum value, a warning is displayed as follows:

TRAS0095I: The total number of timed operations has reached the configured maximum of 10000. 
As new timed operations are created the least recently used timed operations will be removed to 
maintain the total number of tracked timed operations at this level.

You can also use the server dump command to get a full report of all timed operations in the messages.log file, grouped by type, and sorted within each group by average of actual duration.

The following example shows a sample logged message:

[3/14/13 14:01:25:960 CDT] 00000025 TimedOperatio W   
TRAS0080W: Operation websphere.datasource.execute:
jdbc/exampleDS:insert into cities values ("myHomeCity", 106769, "myHomeCountry") took 1.541 ms to complete,
 which was longer than the expected duration of 0.213 ms based on past observations.

The following example shows a sample automatically generated report in the log:

[12/13/12 7:42:29:509 CST] 0000001d com.ibm.wsspi.timedoperations.TimedOperationService I 
TRAS0092I: 
The following operations took the longest time to run since the last report has been generated:
Operation websphere.datasource.execute:jdbc/exampleDS:insert into cities values ("myHomeCity", 
106769, "myHomeCountry") took 194ms to complete
Operation websphere.datasource.execute:jdbc/exampleDS:select county from cities where name=
"myHomeCity" took 187ms to complete
Operation websphere.datasource.execute:jdbc/exampleDS:drop table cities took 182ms to 
complete\Operation websphere.datasource.execute:jdbc/exampleDS:insert into cities values 
('myHomeCity', 106769, 'myHomeCounty') took 151ms to complete

For the full timed operation configuration reference, see Timed Operations.