Red Hat Training

A Red Hat training course is available for Red Hat JBoss Data Virtualization

6.4. Command Logging

Command logging captures user commands that have been submitted to JBoss Data Virtualization, query plan commands when query planning is performed, and data source commands that are being executed by connectors.
The user command, "START USER COMMAND", is logged when JBoss Data Virtualization starts working on the query for the first time. This does not include the time the query was waiting in the queue. A corresponding user command, "END USER COMMAND", is logged when the request is complete (that is, when the statement is closed or all the batches are retrieved). There is only one pair of these for every user query.
The query plan command, "PLAN USER COMMAND", is logged when JBoss Data Virtualization finishes the query planning process. There is no corresponding ending log entry.
Non-plan user events are logged at the INFO level.
The data source command, "START DATA SRC COMMAND", is logged when a query is sent to the data source. And a corresponding data source command, "END SRC COMMAND", is logged when the execution is closed (that is, all the rows has been read). There can be one pair for each data source query that has been executed by JBoss Data Virtualization, and there can be number of pairs depending upon your query.
With this information being captured, the overall query execution time can be calculated. Additionally, each source query execution time can be calculated. If the overall query execution time is showing a performance issue, then look at each data source execution time to see where the issue may be.
With this information being captured, the overall query execution time in Teiid can be calculated. Additionally, each source query execution time can be calculated. If the overall query execution time is showing a performance issue, then look at each data source execution time to see where the issue maybe.
To enable command logging to the default log location, simply enable the DEBUG level of logging for the org.teiid.COMMAND_LOG context. You can use the Admin Console to enable or disable it. Note that you can also turn on command logging using the web-console.
To enable command logging to an alternative file location, configure a separate file appender for the DETAIL logging of the org.teiid.COMMAND_LOG context. An example of this is shown below and can also be found in the standalone.xml file. 
<periodic-rotating-file-handler name="COMMAND_FILE">
    <level name="DEBUG" />
    <formatter>
        <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n" />
    </formatter>
    <file relative-to="jboss.server.log.dir" path="command.log" />
    <suffix value=".yyyy-MM-dd" />
</periodic-rotating-file-handler>
 
<logger category="org.teiid.COMMAND_LOG">
    <level name="DEBUG" />
    <handlers>
        <handler name="COMMAND_FILE" />
    </handlers>
</logger>
See Red Hat JBoss Data Virtualization Development Guide: Server Development for information on developing a custom logging solution if file based (or any other built-in log4j) logging is not sufficient.
The following is an example of a data source command and what one would look like when printed to the command log: 
2012-02-22 16:01:53,712 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue11 START DATA SRC COMMAND: startTime=2012-02-22 16:01:53.712 
requestID=Ku4/dgtZPYk0.5 sourceCommandID=4 txID=null modelName=DTHCP translatorName=jdbc-simple sessionID=Ku4/dgtZPYk0 
principal=user@teiid-security 
sql=HCP_ADDR_XREF.HUB_ADDR_ID, CPN_PROMO_HIST.PROMO_STAT_DT FROM CPN_PROMO_HIST, HCP_ADDRESS, HCP_ADDR_XREF 
WHERE (HCP_ADDRESS.ADDR_ID = CPN_PROMO_HIST.SENT_ADDR_ID) AND (HCP_ADDRESS.ADDR_ID = HCP_ADDR_XREF.ADDR_ID) AND 
(CPN_PROMO_HIST.PROMO_STAT_CD NOT LIKE 'EMAIL%') AND (CPN_PROMO_HIST.PROMO_STAT_CD <> 'SENT_EM') AND 
(CPN_PROMO_HIST.PROMO_STAT_DT > {ts'2010-02-22 16:01:52.928'})
Note the following pieces of information:
  • modelName: this represents the physical model for the data source that the query is being issued.
  • translatorName: shows type of translator used to communicate to the data source.
  • principal: shows the user account who submitted the query
  • startTime/endTime: the time of the action, which is based on the type command being executed.
  • sql: is the command submitted to the translator for execution, which is NOT necessarily the final sql command submitted to the actual data source. But it does show what the query engine decided to push down.