+

Search Tips   |   Advanced Search

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.

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 we run the server dump command, the timed operation feature will generate a report containing information about all operations it has tracked. We 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 containing the ten longest JDBC timed operations. The frequency and enablement of this report is configurable in server.xml, with a default of once per day (24 hours).

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

We 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:

We 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, we can disable the timed operations feature. We can use the following example to configure the maxNumberTimedOperations attribute:

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. 
We 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, we can disable the timed operations feature.

If you set the value of the com.ibm.timedOperations.autoCleanup WebSphere environment variable to true, the server automatically limits the number of tracked timed operations to the value specified in the <maxNumberTimedOperations> attribute. A warning is logged when the total number of timed operations reaches the maximum value specified. To limit the number of tracked timed operations, when a new timed operation is required to be tracked, the least recently used timed operation record is deleted. When the number of timed operations that are tracked reaches the specified maximum value, a warning message is displayed as follows:

We 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, '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: Configuration elements in server.xml


Parent topic: Troubleshooting tips