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.
| • |
An overview of the operations for which measuring is supported and the different values that can be measured |
|
| • |
The architecture and technical concepts used for measuring and monitoring |
|
| • |
The properties to control the measuring |
|
| • |
An example which demonstrates how to use the "Measuring Operation Duration" feature |
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.
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 |
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 |
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.
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?
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.
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:
|
|
Default |
Timekeeper[operation= |
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
|
|
Default |
True |
The following section shows an example of how to measure operation duration.
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.
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
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]
