[teiid-issues] [JBoss JIRA] (TEIID-3596) Command logging: last command's log is not ended

[Steven Hawkins (JIRA)]

    [ https://issues.jboss.org/browse/TEIID-3596?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13093480#comment-13093480 ] 

Steven Hawkins commented on TEIID-3596:
---------------------------------------

> But isn't the fact that only next command can complete the log for the previous one (when performed on the same client Statement) affecting the time precision of the logs?

There are multiple notions of when a query ends.  To be consistent we're using when the request is closed on the server side.  There is also when we are done producing batches internally - however for large forward-only results that will always be correlated to the results being read from the client as we do not indefinitely build up results on the server side.

> Or would they?

Any well designed client app should close resources as soon as possible.  The timing also shouldn't be used necessarily as an indication of server performance - that should be measured from a client perspective.  There is also TEIID-3591 to add a CPU utilization measure to the command log as well.

> Command logging: last command's log is not ended
> ------------------------------------------------
>
>                 Key: TEIID-3596
>                 URL: https://issues.jboss.org/browse/TEIID-3596
>             Project: Teiid
>          Issue Type: Bug
>          Components: Query Engine
>    Affects Versions: 8.7.1.6_2
>            Reporter: Jan Stastny
>            Assignee: Steven Hawkins
>
> There are incomplete entries when performing queries on some vdb and examining the org.teiid.COMMAND_LOG entries in server.log.
> From the logs it seems, that the closing entry for a user command is not logged until either another command is performed or the server is shut down.
> The following logs appears right after the command is performed:
> {code:plain}
> [org.teiid.COMMAND_LOG] (New I/O worker #64)         START USER COMMAND:     startTime=2015-07-28 13:43:18.441       requestID=rfFDiTxhxLGL.0        txID=null       sessionID=rfFDiTxhxLGL  applicationName=JDBC    principal=user at teiid-security   vdbName=Portfolio       vdbVersion=1    sql=select * from product
> [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1)       START DATA SRC COMMAND: startTime=2015-07-28 13:43:18.54        requestID=rfFDiTxhxLGL.0        sourceCommandID=0       executionID=0   txID=null       modelName=Accounts      translatorName=translator-h2    sessionID=rfFDiTxhxLGL  principal=user at teiid-security   sql=SELECT g_0.ID, g_0.SYMBOL, g_0.COMPANY_NAME FROM Accounts.PRODUCT AS g_0
> [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue2)       END SRC COMMAND:        endTime=2015-07-28 13:43:18.548 requestID=rfFDiTxhxLGL.0        sourceCommandID=0       executionID=0   txID=null       modelName=Accounts      translatorName=translator-h2    sessionID=rfFDiTxhxLGL  principal=user at teiid-security   finalRowCount=25
> {code}
> while the following appers only when the server is shut down (notice the time difference between this one and preceding ones):
> {code:plain}
> [org.teiid.COMMAND_LOG] (New I/O worker #64)         CANCEL USER COMMAND:    endTime=2015-07-28 13:43:29.152 requestID=rfFDiTxhxLGL.0        txID=null       sessionID=rfFDiTxhxLGL  principal=user at teiid-security   vdbName=Portfolio       vdbVersion=1    finalRowCount=null
> {code}
> If there is another command following, the previous command log entry is completed (but it can take even minutes):
> {code:plain}
> [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue3)       END USER COMMAND:       endTime=2015-07-28 14:18:59.511 requestID=q97k+Z4gwV64.0        txID=null       sessionID=q97k+Z4gwV64  principal=user at teiid-security   vdbName=Portfolio       vdbVersion=1    finalRowCount=25
> {code}
> Also the ending log entry of one command and opening entry of another appear in any order.



--
This message was sent by Atlassian JIRA
(v6.3.15#6346)