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.
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" />
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"/>
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.