Measuring Operation Duration

Tamino is a fast, flexible, and highly scalable DBMS system. However, when writing high-performance, large-scale Tamino applications, the first step in finding potential bottlenecks is to discover where the application spends most of its time.

Tamino API for Java provides basic mechanisms for gathering detailed information about execution times. Tamino API for Java does not include statistical tools to summarize or process the measurement results. Instead, publicly available handler classes can be used to measure values.

•	Operation and Measured Values	An overview of the operations for which measuring is supported and the different values that can be measured
•	Architecture and Technical Concepts	The architecture and technical concepts used for measuring and monitoring
•	Controlling Duration Measurement	The properties to control the measuring
•	Running the Get Personal Example with Duration Measurement	An example which demonstrates how to use the "Measuring Operation Duration" feature

Operation and Measured Values

Measuring support is provided for the following operations in the Tamino API for Java:

Creating new connections in the TConnectionFactory class.
All operations of the various accessor interfaces with the exception of the operations inherited from superinterfaces TAccessor and TInvalidatableAccessor.
All operations in the interfaces TXMLObjectIterator and TNonXMLObjectIterator.
Creating new TXMLObject instances or initializes them by reading data from an InputStream or a Reader.

Measured Values
Accuracy of Measured Values

Measured Values

For the operations listed above, the following values can be measured:

`TotalOperationDuration`	The time taken from the start of the operation until the end of the operation. This is the total processing time within the Tamino API for Java, including the values measured by `XmlParseDuration` and `TotalCommunicationDuration`.
`XmlParseDuration`	The time taken to parse the XML response document.
`TotalCommunicationDuration`	The time taken from submitting the request to Tamino until the response document is completely received. Note that this includes the value for `TaminoServerDuration`.
`TaminoServerDuration`	The time taken to process the request in the Tamino XML Server.

Even if the expected result should produce values greater than zero, this will not necessarily be the case for all values measured. Moreover, this depends on the operation performed. For example, when deleting a document no relevant parsing of response documents needs to be done.

Accuracy of Measured Values

All values are measured in milliseconds. Note that while the unit of time of the return value is a millisecond, the granularity of the value depends on the operating system and may in some cases be larger. For example, many operating systems measure time in units of tens of milliseconds. Hence fast operations may deliver a value of zero because their duration was below the minimum granularity. Also note that the sum of individual durations may not be exactly equal to the total operation duration. This is because measurements are made in different processes and possibly even on different computers.

The "Measuring Operation Time" feature of the Tamino API for Java cannot answer the question: Exactly how long does operation x with data y take?. Rather, it helps you to answers questions such as: Where does the application spend most of its time? or: Does the program run faster after making a change?

Architecture and Technical Concepts

The Tamino API for Java uses the popular log4j API to trace the measured values. log4j is an open source project to develop a logging package for Java. It allows the developer to control the output of log statements with arbitrary granularity. It is fully configurable at runtime using external configuration files. This documentation does not describe the log4j API. The latest log4j version and documentation can be found at http://logging.apache.org/.

Configuration of the log4j environment is typically done at the initialization of the application, preferably by reading a configuration file. Please see the log4j documentation for further information.

The log4j logger used by the Tamino API for Java for measuring operation duration is named com.softwareag.tamino.db.api.logging.

Controlling Duration Measurement

The following Java properties can be set to control the measuring:

`com.softwareag.tamino.db.api.logging.DurationLogging`
Description	Specifies whether duration measurement in the Tamino API for Java is enabled.
True	Perform duration measurement.
False	Do not perform duration measurement.
Default	False

`com.softwareag.tamino.db.api.logging.DurationLoggingLevel`
Description	Choose the level used by the duration logging for the messages sent to the underlying log4j logger.
Default	DEBUG

`com.softwareag.tamino.db.api.logging.DurationLoggingPattern`
Description	A simple pattern to configure the output string used by the duration logging for the messages. The name of the operation and the measured duration values are symbolized by the following wildcards: `%OPERATION%` `%TOTAL_OPERATION_DURATION%` `%TOTAL_COMMUNICATION_DURATION%` `%TAMINO_SERVER_DURATION%` `%XML_PARSE_DURATION%`
Default	Timekeeper[operation=`%OPERATION%`, totalOperationDuration=`%TOTAL_OPERATION_DURATION%`, totalCommunicationDuration=`%TOTAL_COMMUNICATION_DURATION%`, taminoServerDuration=`%TAMINO_SERVER_DURATION%`, xmlParseDuration=`%XML_PARSE_DURATION%`]

com.softwareag.tamino.db.api.logging.DurationLoggingPattern

Description

A simple pattern to configure the output string used by the duration logging for the messages. The name of the operation and the measured duration values are symbolized by the following wildcards:

%OPERATION%
%TOTAL_OPERATION_DURATION%
%TOTAL_COMMUNICATION_DURATION%
%TAMINO_SERVER_DURATION%
%XML_PARSE_DURATION%

Default

Timekeeper[operation=%OPERATION%, totalOperationDuration=%TOTAL_OPERATION_DURATION%, totalCommunicationDuration=%TOTAL_COMMUNICATION_DURATION%, taminoServerDuration=%TAMINO_SERVER_DURATION%, xmlParseDuration=%XML_PARSE_DURATION%]

`com.softwareag.tamino.db.api.common.TOptimizationHints.isOn`
Description	The Tamino API for Java tries to optimize the interpretation of the Tamino response. A side effect is that sometimes the value for the `TaminoServerDuration` cannot be provided. This property does not really influence the duration measurement itself, so you may consider setting it to False to get as much measurement information as possible.
Default	True

Running the Get Personal Example with Duration Measurement

The following section shows an example of how to measure operation duration.

Prerequisites for Running the Samples
Configure the log4j Environment
Run Example with Measuring Activated

Prerequisites for Running the Samples

Include the .jar files TaminoAPI4J.jar, JavaTaminoAPIExamples.jar, log4j.jar, xercesImpl.jar and xmlParserAPIs.jar in your class path. All files are distributed along with the Tamino API for Java.

Configure the log4j Environment

This sample log4j configuration file results in writing the output of the duration measurement in a file Durations.txt.

# Print only messages of the Tamino API for Java duration measurement.
# Set logger level to DEBUG and its only appender to 
log4j.logger.com.softwareag.tamino.db.api.logging=DEBUG, A
# A is set to be a FileAppender.
log4j.appender.A=org.apache.log4j.FileAppender
log4j.appender.A.File=Durations.txt.
# A uses PatternLayout to configure the output string
log4j.appender.A.layout=org.apache.log4j.PatternLayout
log4j.appender.A.layout.ConversionPattern=%m%n

Run Example with Measuring Activated

The following command executes the Java interpreter:

java -Dcom.softwareag.tamino.db.api.logging.DurationLogging=true com.softwareag.tamino.db.api.examples.person.ProcessPersonsWithSchema

The output in the Durations.txt file will look like the following:

Timekeeper[operation=newConnection, totalOperationDuration=109, totalCommunicationDuration=31, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=isServerAlive, totalOperationDuration=312, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=281]
Timekeeper[operation=getServerVersion, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=getServerAPIVersion, totalOperationDuration=16, totalCommunicationDuration=16, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=getAPIVersion, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=newXMLObject, totalOperationDuration=15, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=readFrom, totalOperationDuration=16, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=16]
Timekeeper[operation=define, totalOperationDuration=390, totalCommunicationDuration=390, taminoServerDuration=370, xmlParseDuration=0]
Timekeeper[operation=newXMLObject, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=newXMLObject, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=readFrom, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=insert, totalOperationDuration=94, totalCommunicationDuration=78, taminoServerDuration=80, xmlParseDuration=16]
Timekeeper[operation=newXMLObject, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=readFrom, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=insert, totalOperationDuration=78, totalCommunicationDuration=62, taminoServerDuration=50, xmlParseDuration=16]
Timekeeper[operation=newXMLObject, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=readFrom, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=insert, totalOperationDuration=78, totalCommunicationDuration=62, taminoServerDuration=20, xmlParseDuration=16]
Timekeeper[operation=newXMLObject, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=readFrom, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=insert, totalOperationDuration=47, totalCommunicationDuration=31, taminoServerDuration=10, xmlParseDuration=16]
Timekeeper[operation=newXMLObject, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=readFrom, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=insert, totalOperationDuration=47, totalCommunicationDuration=31, taminoServerDuration=10, xmlParseDuration=16]
Timekeeper[operation=query, totalOperationDuration=31, totalCommunicationDuration=15, taminoServerDuration=10, xmlParseDuration=16]
Timekeeper[operation=hasNext, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=query, totalOperationDuration=47, totalCommunicationDuration=47, taminoServerDuration=10, xmlParseDuration=0]
Timekeeper[operation=hasNext, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=next, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=hasNext, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=next, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=hasNext, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=next, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=hasNext, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=next, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=hasNext, totalOperationDuration=0, totalCommunicationDuration=0, taminoServerDuration=0, xmlParseDuration=0]
Timekeeper[operation=delete, totalOperationDuration=32, totalCommunicationDuration=32, taminoServerDuration=30, xmlParseDuration=0]
Timekeeper[operation=undefine, totalOperationDuration=578, totalCommunicationDuration=578, taminoServerDuration=551, xmlParseDuration=0]