Fix Pack 8550

Liberty profile: 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.

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" />
You can also use the maxNumberTimedOperations attribute to log a warning when the total number of timed operations reaches the value specified by this attribute. The number of timed operations is monitored and useful to know since each timed operation is allocated memory from the heap, and if you find that the number of timed operations is excessive, you can disable the timed operations feature. You can use the following example to configure the maxNumberTimedOperations attribute:
<timedOperation enableReport="false" reportFrequency="12" maxNumberTimedOperations="10000"/>
This example results in a warning message in the log as follows when the number of timed operations exceeds 10000:
[4/18/13 23:01:37:316 EDT] 0000002c com.ibm.wsspi.timedoperations.TimedOperationService W TRAS0094I: 
The total number of timed operations is 10000, which exceeds the configured maximum number of 10000. 
You can also find the number of timed operations in the report that is periodically generated to the logs.
If you find that the number of timed operations is excessive, you can disable the timed operations feature. 

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.

In order to get detailed information about the timed operations that have an abnormal behavior, change the traceSpecification attribute to include the trace string "com.ibm.ws.timedoperations.*=FINE".

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, 'myHomeCounty') 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 the timedOperation element in the following topic: Liberty profile: Configuration elements in the server.xml file


Icon that indicates the type of topic Concept topic

Terms and conditions for information centers | Feedback


Timestamp icon Last updated: Monday, 21 April 2014
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=phil&product=was-express-iseries&topic=cwlp_timeop
File name: cwlp_timeop.html